Record terraform run result metadata (#1094)

liyu-ma · web-flow · commit a9582b496e5c · 2026-03-12T12:13:47.000+10:00
### Context We want to record terraform action success/failure or timeout error for stats purpose. Add logic to scan terraform logs to capture those info. ### Change - Add a new field `result` to terraform execution metadata record two flags `"success": true/false` and `"timed_out": true/false }` - Improve the code so time elapsed can be captured even when the terraform action failed. - Update terraform azapi timeout to 60 mins, and corresponding pipeline timeout to 2hr See `result` field appended: <img width="2586" height="91" alt="image" src="https://github.com/user-attachments/assets/df3c1cc0-bbde-4f2e-90f8-cd3a24fd3872" />
diff --git a/modules/python/terraform/extract_terraform_operation_metadata.py b/modules/python/terraform/extract_terraform_operation_metadata.py
@@ -4,8 +4,18 @@
 import os
 import datetime
 
-# Regex to extract: full module path and time
-PATTERN = re.compile(r"(module\.[^:]+): (?:Creation|Destruction) complete after (\d+h\d+m\d+s|\d+h\d+s|\d+m\d+s|\d+s)")
+# Regex to extract: full module path and time from completion lines
+COMPLETE_PATTERN = re.compile(r"(module\.[^:]+): (?:Creation|Destruction) complete after (\d+h\d+m\d+s|\d+h\d+s|\d+m\d+s|\d+s)")
+
+# Regex to extract: full module path from initial "Creating"/"Destroying" lines
+# e.g. module.azapi["ccp-provisioning-H4"].azapi_resource.aks_cluster: Creating...
+# e.g. module.azapi["ccp-provisioning-H4"].azapi_resource.aks_cluster: Destroying
+START_PATTERN = re.compile(r"(module\.[^:]+): (?:Creating|Destroying)")
+
+# Regex to extract: elapsed time from "Still creating/destroying..." lines
+# e.g. module.azapi[...].azapi_resource.aks_cluster: Still creating... [29m51s elapsed]
+# or:  module.azapi[...].azapi_resource.aks_cluster: Still destroying... 00m40s elapsed]
+ELAPSED_PATTERN = re.compile(r"Still (?:creating|destroying)\.\.\. \[?(\d+h\d+m\d+s|\d+h\d+s|\d+m\d+s|\d+s) elapsed\]")
 
 def time_to_seconds(time_str):
     try:
@@ -33,7 +43,30 @@ def parse_module_path(full_path):
 
     return module_name, submodule_path, resource_name
 
+def build_result(full_path, time_str, run_id, _command_type, _scenario_type, _scenario_name, completed, timed_out):
+    seconds = time_to_seconds(time_str)
+    module, submodule, resource = parse_module_path(full_path)
+
+    return {
+        "timestamp": datetime.datetime.now().isoformat(),
+        "run_id": run_id,
+        "scenario_type": _scenario_type,
+        "scenario_name": _scenario_name,
+        "module_name": module,
+        "submodule_name": submodule,
+        "resource_name": resource,
+        "action": _command_type,
+        "time_taken_seconds": seconds,
+        "result": {"success": completed, "timed_out": timed_out}
+    }
+
 def process_terraform_logs(log_path, _command_type, _scenario_type, _scenario_name):
+    """Process terraform log file and collect operation metadata for each run.
+    A single log file may contain multiple runs of the same module when failures
+    trigger retries. Each run starts with a "Creating..."/"Destroying..." line.
+    We collect data for all runs: successful runs use the completion time, and
+    failed runs use the last reported elapsed time as a fallback.
+    """
     log_file = os.path.join(log_path, f"terraform_{_command_type}.log")
     run_id = os.getenv("RUN_ID", "")
     results = []
@@ -43,25 +76,44 @@ def process_terraform_logs(log_path, _command_type, _scenario_type, _scenario_na
         return results
 
     try:
+        current_full_path = None
+        current_elapsed_time_str = None
+        current_completed = False
+        current_timed_out = False
+
         with open(log_file, "r", encoding='utf-8') as f:
             for line in f:
-                match = PATTERN.search(line)
+                # Check for timeout on every line before any continue statements
+                if "context deadline exceeded" in line:
+                    current_timed_out = True
+
+                start_match = START_PATTERN.search(line)
+                if start_match:
+                    # A new run is starting; flush the previous run if it was incomplete
+                    if current_full_path and not current_completed and current_elapsed_time_str:
+                        results.append(build_result(current_full_path, current_elapsed_time_str, run_id, _command_type, _scenario_type, _scenario_name, False, current_timed_out))
+
+                    current_full_path = start_match.group(1)
+                    current_elapsed_time_str = None
+                    current_completed = False
+                    current_timed_out = False
+                    continue
+
+                match = COMPLETE_PATTERN.search(line)
                 if match:
                     full_path, time_str = match.groups()
-                    seconds = time_to_seconds(time_str)
-                    module, submodule, resource = parse_module_path(full_path)
-
-                    results.append({
-                        "timestamp": datetime.datetime.now().isoformat(),
-                        "run_id": run_id,
-                        "scenario_type": _scenario_type,
-                        "scenario_name": _scenario_name,
-                        "module_name": module,
-                        "submodule_name": submodule,
-                        "resource_name": resource,
-                        "action": _command_type,
-                        "time_taken_seconds": seconds
-                    })
+                    current_completed = True
+                    results.append(build_result(full_path, time_str, run_id, _command_type, _scenario_type, _scenario_name, True, False))
+                    continue
+
+                elapsed_match = ELAPSED_PATTERN.search(line)
+                if elapsed_match:
+                    current_elapsed_time_str = elapsed_match.group(1)
+                    continue
+
+        # Flush the last run if it was incomplete
+        if current_full_path and not current_completed and current_elapsed_time_str:
+            results.append(build_result(current_full_path, current_elapsed_time_str, run_id, _command_type, _scenario_type, _scenario_name, False, current_timed_out))
     except Exception as e:
         print(f"[ERROR] Failed to process log file '{log_file}': {e}")
 
diff --git a/modules/python/tests/test_extract_terraform_operation_metadata.py b/modules/python/tests/test_extract_terraform_operation_metadata.py
@@ -169,5 +169,142 @@ def test_process_terraform_logs_with_invalid_log_line(self, mock_open_file, mock
         mock_open_file.assert_called_once_with('/fake/path/terraform_apply.log', 'r', encoding='utf-8')
         mock_isfile.assert_called_once_with("/fake/path/terraform_apply.log")
 
+    @patch("os.path.isfile", return_value=True)
+    @patch("builtins.open", new_callable=mock_open, read_data=(
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [10m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... 20m0s elapsed]\n"
+        "│ Error: Failed to create/update resource\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [15m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... 25m30s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... 30m45s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creation complete after 30m55s [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-14acb1f24219/resourceGroups/57202-578c08a2/providers/Microsoft.ContainerService/managedClusters/ccp-provisioning-H4]\n"
+    ))
+    def test_process_terraform_logs_with_failed_run_and_retries(self, mock_open_file, mock_isfile):
+        os.environ["RUN_ID"] = "9988776655"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="perf-eval",
+          _scenario_name="test_scenario_name",
+        )
+
+        self.assertEqual(len(results), 3)
+
+        # First failed run - last elapsed was 20m0s = 1200s
+        self.assertEqual(results[0]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["time_taken_seconds"], 1200)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": False})
+
+        # Second failed run (retry 1) - last elapsed was 25m30s = 1530s
+        self.assertEqual(results[1]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[1]["resource_name"], "aks_cluster")
+        self.assertEqual(results[1]["time_taken_seconds"], 1530)
+        self.assertEqual(results[1]["result"], {"success": False, "timed_out": False})
+
+        # Third failed run (retry 2) - last elapsed was 30m45s = 1845s
+        self.assertEqual(results[2]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[2]["resource_name"], "aks_cluster")
+        self.assertEqual(results[2]["time_taken_seconds"], 1855)
+        self.assertEqual(results[2]["result"], {"success": True, "timed_out": False})
+
+        mock_open_file.assert_called_once_with('/fake/path/terraform_apply.log', 'r', encoding='utf-8')
+        mock_isfile.assert_called_once_with("/fake/path/terraform_apply.log")
+
+    @patch("os.path.isfile", return_value=True)
+    @patch("builtins.open", new_callable=mock_open, read_data=(
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [10m0s elapsed]\n"
+        "creating/updating Resource: (ResourceId\n"
+        "/subscriptions/b8ceb4e5/resourceGroups/58296/providers/Microsoft.ContainerService/managedClusters/ccp-H8\n"
+        "│ Error: creating/updating Resource: context deadline exceeded\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creation complete after 8m30s [id=/subscriptions/b8ceb4e5/resourceGroups/58296/providers/Microsoft.ContainerService/managedClusters/ccp-H8]\n"
+    ))
+    def test_process_terraform_logs_with_timeout_and_retry(self, mock_open_file, mock_isfile):
+        os.environ["RUN_ID"] = "1234567890"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="perf-eval",
+          _scenario_name="test_scenario_name",
+        )
+
+        self.assertEqual(len(results), 2)
+
+        # First run timed out
+        self.assertEqual(results[0]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["time_taken_seconds"], 600)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": True})
+
+        # Retry succeeded
+        self.assertEqual(results[1]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[1]["resource_name"], "aks_cluster")
+        self.assertEqual(results[1]["time_taken_seconds"], 510)
+        self.assertEqual(results[1]["result"], {"success": True, "timed_out": False})
+
+        mock_open_file.assert_called_once_with('/fake/path/terraform_apply.log', 'r', encoding='utf-8')
+        mock_isfile.assert_called_once_with("/fake/path/terraform_apply.log")
+
+    @patch("os.path.isfile", return_value=True)
+    @patch("builtins.open", new_callable=mock_open, read_data=(
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [10m0s elapsed]\n"
+        "│ Error: Failed to create/update resource\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [10m0s elapsed]\n"
+        "│ Error: creating/updating Resource: context deadline exceeded\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Creating...\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [5m0s elapsed]\n"
+        "module.azapi[\"ccp\"].azapi_resource.aks_cluster: Still creating... [10m0s elapsed]\n"
+        "│ Error: creating/updating Resource: context deadline exceeded\n"
+    ))
+    def test_process_terraform_logs_with_all_retries_failed(self, mock_open_file, mock_isfile):
+        os.environ["RUN_ID"] = "1112223334"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="perf-eval",
+          _scenario_name="test_scenario_name",
+        )
+
+        self.assertEqual(len(results), 3)
+
+        # First run failed with a non-timeout error
+        self.assertEqual(results[0]["run_id"], "1112223334")
+        self.assertEqual(results[0]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["time_taken_seconds"], 600)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": False})
+
+        # Second run timed out
+        self.assertEqual(results[1]["run_id"], "1112223334")
+        self.assertEqual(results[1]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[1]["resource_name"], "aks_cluster")
+        self.assertEqual(results[1]["time_taken_seconds"], 600)
+        self.assertEqual(results[1]["result"], {"success": False, "timed_out": True})
+
+        # Third run timed out
+        self.assertEqual(results[2]["run_id"], "1112223334")
+        self.assertEqual(results[2]["module_name"], "azapi[\"ccp\"]")
+        self.assertEqual(results[2]["resource_name"], "aks_cluster")
+        self.assertEqual(results[2]["time_taken_seconds"], 600)
+        self.assertEqual(results[2]["result"], {"success": False, "timed_out": True})
+
+        mock_open_file.assert_called_once_with('/fake/path/terraform_apply.log', 'r', encoding='utf-8')
+        mock_isfile.assert_called_once_with("/fake/path/terraform_apply.log")
+
 if __name__ == "__main__":
     unittest.main()
diff --git a/modules/terraform/azure/azapi/main.tf b/modules/terraform/azure/azapi/main.tf
@@ -62,4 +62,8 @@ resource "azapi_resource" "aks_cluster" {
   response_export_values = [
     "properties.fqdn"
   ]
+
+  timeouts {
+    create = "60m"
+  }
 }
diff --git a/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H2.yml b/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H2.yml
@@ -32,5 +32,5 @@ stages:
           max_parallel: 1
           credential_type: service_connection
           ssh_key_enabled: false
-          timeout_in_minutes: 60
+          timeout_in_minutes: 120
           retry_attempt_count: 0
diff --git a/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H4.yml b/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H4.yml
@@ -32,5 +32,5 @@ stages:
           max_parallel: 1
           credential_type: service_connection
           ssh_key_enabled: false
-          timeout_in_minutes: 60
+          timeout_in_minutes: 120
           retry_attempt_count: 0
diff --git a/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H8.yml b/pipelines/perf-eval/Hyperscale Cluster Benchmark/ccp-provisioning-H8.yml
@@ -32,5 +32,5 @@ stages:
           max_parallel: 1
           credential_type: service_connection
           ssh_key_enabled: false
-          timeout_in_minutes: 60
+          timeout_in_minutes: 120
           retry_attempt_count: 0
diff --git a/steps/terraform/run-command.yml b/steps/terraform/run-command.yml
@@ -41,7 +41,7 @@ steps:
         fi
 
         set +e
-        terraform ${{ parameters.command }} --auto-approve ${{ parameters.arguments }} -var-file $terraform_input_file -var json_input="$terraform_input_variables" | tee terraform_${{ parameters.command }}.log
+        terraform ${{ parameters.command }} --auto-approve ${{ parameters.arguments }} -var-file $terraform_input_file -var json_input="$terraform_input_variables" 2>&1 | tee terraform_${{ parameters.command }}.log
         exit_code=${PIPESTATUS[0]}
         if [[ $exit_code -ne 0 ]]; then
           if [[ ${{ parameters.command }} == "apply" && "$CLOUD" == "azure" ]]; then

Original file line number	Diff line number	Diff line change
`@@ -62,4 +62,8 @@ resource "azapi_resource" "aks_cluster" {`
`62`	`62`	`response_export_values = [`
`63`	`63`	`"properties.fqdn"`
`64`	`64`	`]`
	`65`	`+`
	`66`	`+ timeouts {`
	`67`	`+ create = "60m"`
	`68`	`+ }`
`65`	`69`	`}`