Improve robustness on terraform log regex matching (#1098)

liyu-ma · web-flow · commit f8fb2831e038 · 2026-03-18T11:22:17.000+10:00
### bugfixes 

- Relax the regex for time elapsed to accommodate `terraform destroy`
case
- Provide a default failure case with elapsed 0 seconds when no duration
captured
- Use `--no-wait` and polling for resource group deletion
diff --git a/modules/python/terraform/extract_terraform_operation_metadata.py b/modules/python/terraform/extract_terraform_operation_metadata.py
@@ -15,7 +15,7 @@
 # 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\]")
+ELAPSED_PATTERN = re.compile(r"Still (?:creating|destroying)\.\.\..*?(\d+h\d+m\d+s|\d+h\d+s|\d+m\d+s|\d+s)\s+elapsed\]")
 
 def time_to_seconds(time_str):
     try:
@@ -90,8 +90,8 @@ def process_terraform_logs(log_path, _command_type, _scenario_type, _scenario_na
                 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))
+                    if current_full_path and not current_completed:
+                        results.append(build_result(current_full_path, current_elapsed_time_str or "0s", run_id, _command_type, _scenario_type, _scenario_name, False, current_timed_out))
 
                     current_full_path = start_match.group(1)
                     current_elapsed_time_str = None
@@ -112,8 +112,8 @@ def process_terraform_logs(log_path, _command_type, _scenario_type, _scenario_na
                     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))
+        if current_full_path and not current_completed:
+            results.append(build_result(current_full_path, current_elapsed_time_str or "0s", 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
@@ -306,5 +306,150 @@ def test_process_terraform_logs_with_all_retries_failed(self, mock_open_file, mo
         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-provisioning-H2"].azapi_resource.aks_cluster: Destroying... [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-14acb1f24219/resourceGroups/59393-51f48219/providers/Microsoft.ContainerService/managedClusters/ccp-provisioning-H2]\n'
+        'module.azapi["ccp-provisioning-H2"].azapi_resource.aks_cluster: Still destroying... [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-...ce/managedClusters/ccp-provisioning-H2, 00m10s elapsed]\n'
+    ))
+    def test_process_terraform_logs_still_destroying_with_id_prefix(self, mock_open_file, mock_isfile):
+        """Verify metadata record is created when 'Still destroying' line contains id= prefix before elapsed time."""
+        os.environ["RUN_ID"] = "4455667788"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="destroy",
+          _scenario_type="ccp",
+          _scenario_name="provisioning",
+        )
+
+        self.assertEqual(len(results), 1)
+        self.assertEqual(results[0]["run_id"], "4455667788")
+        self.assertEqual(results[0]["module_name"], 'azapi["ccp-provisioning-H2"]')
+        self.assertEqual(results[0]["submodule_name"], "azapi_resource")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["action"], "destroy")
+        self.assertEqual(results[0]["time_taken_seconds"], 10)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": False})
+        mock_open_file.assert_called_once_with('/fake/path/terraform_destroy.log', 'r', encoding='utf-8')
+        mock_isfile.assert_called_once_with("/fake/path/terraform_destroy.log")
+
+    @patch("os.path.isfile", return_value=True)
+    @patch("builtins.open", new_callable=mock_open, read_data=(
+        'module.azapi["ccp-provisioning-H2"].azapi_resource.aks_cluster: Creating... [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-14acb1f24219/resourceGroups/59393-51f48219/providers/Microsoft.ContainerService/managedClusters/ccp-provisioning-H2]\n'
+        'module.azapi["ccp-provisioning-H2"].azapi_resource.aks_cluster: Still creating... [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-...ce/managedClusters/ccp-provisioning-H2, 10m0s elapsed]\n'
+        'module.azapi["ccp-provisioning-H2"].azapi_resource.aks_cluster: Still creating... [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-...ce/managedClusters/ccp-provisioning-H2, 20m0s elapsed]\n'
+        'module.azapi["ccp-provisioning-H2"].azapi_resource.aks_cluster: Creation complete after 25m30s [id=/subscriptions/b8ceb4e5-f05b-4562-a9f5-14acb1f24219/resourceGroups/59393-51f48219/providers/Microsoft.ContainerService/managedClusters/ccp-provisioning-H2]\n'
+    ))
+    def test_process_terraform_logs_still_creating_with_id_prefix_then_complete(self, mock_open_file, mock_isfile):
+        """Verify that 'Still creating' lines with id= prefix are parsed and final completion record is used."""
+        os.environ["RUN_ID"] = "5566778899"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="ccp",
+          _scenario_name="provisioning",
+        )
+
+        self.assertEqual(len(results), 1)
+        self.assertEqual(results[0]["run_id"], "5566778899")
+        self.assertEqual(results[0]["module_name"], 'azapi["ccp-provisioning-H2"]')
+        self.assertEqual(results[0]["submodule_name"], "azapi_resource")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["action"], "apply")
+        self.assertEqual(results[0]["time_taken_seconds"], 1530)
+        self.assertEqual(results[0]["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: Destroying... [id=/subscriptions/b8ceb4e5/resourceGroups/59393/providers/Microsoft.ContainerService/managedClusters/ccp-H2]\n'
+        '│ Error: deleting Resource: unexpected status 409\n'
+    ))
+    def test_process_terraform_logs_failure_without_elapsed_line(self, mock_open_file, mock_isfile):
+        """Verify a failure record with 0s elapsed is created when there is no 'Still destroying' line."""
+        os.environ["RUN_ID"] = "6677889900"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="destroy",
+          _scenario_type="ccp",
+          _scenario_name="provisioning",
+        )
+
+        self.assertEqual(len(results), 1)
+        self.assertEqual(results[0]["run_id"], "6677889900")
+        self.assertEqual(results[0]["module_name"], 'azapi["ccp"]')
+        self.assertEqual(results[0]["submodule_name"], "azapi_resource")
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["action"], "destroy")
+        self.assertEqual(results[0]["time_taken_seconds"], 0)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": False})
+        mock_open_file.assert_called_once_with('/fake/path/terraform_destroy.log', 'r', encoding='utf-8')
+        mock_isfile.assert_called_once_with("/fake/path/terraform_destroy.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'
+        '│ Error: creating Resource: context deadline exceeded\n'
+    ))
+    def test_process_terraform_logs_timeout_without_elapsed_line(self, mock_open_file, mock_isfile):
+        """Verify a failure record with timed_out=True and 0s elapsed is created when timeout occurs without elapsed lines."""
+        os.environ["RUN_ID"] = "7788990011"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="ccp",
+          _scenario_name="provisioning",
+        )
+
+        self.assertEqual(len(results), 1)
+        self.assertEqual(results[0]["run_id"], "7788990011")
+        self.assertEqual(results[0]["module_name"], 'azapi["ccp"]')
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["action"], "apply")
+        self.assertEqual(results[0]["time_taken_seconds"], 0)
+        self.assertEqual(results[0]["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")
+
+    @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'
+        '│ Error: creating Resource: unexpected status 409\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/59393/providers/Microsoft.ContainerService/managedClusters/ccp-H2]\n'
+    ))
+    def test_process_terraform_logs_retry_after_immediate_failure(self, mock_open_file, mock_isfile):
+        """Verify first run records 0s failure when it fails immediately, and retry succeeds normally."""
+        os.environ["RUN_ID"] = "8899001122"
+
+        results = process_terraform_logs(
+          log_path="/fake/path",
+          _command_type="apply",
+          _scenario_type="ccp",
+          _scenario_name="provisioning",
+        )
+
+        self.assertEqual(len(results), 2)
+
+        # First run failed immediately - no elapsed time
+        self.assertEqual(results[0]["module_name"], 'azapi["ccp"]')
+        self.assertEqual(results[0]["resource_name"], "aks_cluster")
+        self.assertEqual(results[0]["time_taken_seconds"], 0)
+        self.assertEqual(results[0]["result"], {"success": False, "timed_out": False})
+
+        # 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")
+
 if __name__ == "__main__":
     unittest.main()
diff --git a/steps/cleanup-resources.yml b/steps/cleanup-resources.yml
@@ -31,7 +31,24 @@ steps:
     fi
 
     echo "Delete resource group $RUN_ID"
-    az group delete --name $RUN_ID --yes
+    az group delete --name $RUN_ID --yes --no-wait
+
+    # Poll until the resource group is fully deleted or timeout after 20 minutes
+    TIMEOUT=1200
+    INTERVAL=30
+    WAIT_TIME=0
+    while [ $WAIT_TIME -lt $TIMEOUT ]; do
+      if ! az group show --name "$RUN_ID" &>/dev/null; then
+        echo "Resource group $RUN_ID deleted successfully."
+        exit 0
+      fi
+      echo "Resource group $RUN_ID still exists. Waiting... ($WAIT_TIME/$TIMEOUT seconds elapsed)"
+      sleep $INTERVAL
+      WAIT_TIME=$((WAIT_TIME + INTERVAL))
+    done
+
+    echo "##vso[task.logissue type=error;] Resource group $RUN_ID was not deleted within $TIMEOUT seconds."
+    exit 1
   displayName: "Destroy Resource Group"
   condition: and(${{ eq(parameters.cloud, 'azure') }}, ne(variables['SKIP_RESOURCE_MANAGEMENT'], 'true'))
   env:
