diff --git a/modules/python/terraform/extract_terraform_operation_metadata.py b/modules/python/terraform/extract_terraform_operation_metadata.py index 90ab816246..085f9a5b01 100644 --- 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 index 9d4ab33ed0..86bc045019 100644 --- 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 index 172a885256..ceee7ea6ab 100644 --- 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: