diff --git a/CHANGELOG.md b/CHANGELOG.md index fcec23b87..419e22ce9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -29,6 +29,7 @@ See [Legacy Airlock & migration](docs/azure-tre-overview/airlock.md#legacy-airlo * Add weekly and manual builds for Dockerfiles and Porter bundles, with selected pull request builds. Retry a failed target once and report final results. ([#5088](https://github.com/microsoft/AzureTRE/issues/5088)) BUG FIXES: +* Record bounded, redacted operation-polling diagnostics without retrying HTTP failures. ([#5202](https://github.com/microsoft/AzureTRE/issues/5202)) * Forward explicit Nexus consent from the Airlock test command. Reject invalid arguments and unsupported deployment reuse. (`build-scripts` 1.1.1) ([#5201](https://github.com/microsoft/AzureTRE/issues/5201)) * Document slash-command coverage and remove the obsolete MLflow test selection. ([#5131](https://github.com/microsoft/AzureTRE/issues/5131)) * Require Nexus consent, restore firewall settings after tests and give shared-service test groups separate time budgets. ([#5132](https://github.com/microsoft/AzureTRE/issues/5132)) diff --git a/docs/tre-developers/end-to-end-tests.md b/docs/tre-developers/end-to-end-tests.md index b1a516d91..3ed4cd3e8 100644 --- a/docs/tre-developers/end-to-end-tests.md +++ b/docs/tre-developers/end-to-end-tests.md @@ -25,6 +25,17 @@ Use the "Run and Debug" panel within Visual Studio Code, select "E2E Extended", - This will also use `/workspaces/AzureTRE/core/private.env` file for other values. +## Investigate operation-polling failures + +Unexpected HTTP responses fail operation polling. HTTP 500 is not retried or treated as successful deletion. +The error log records a UTC timestamp, method, recognised operation path, status, media type, body size and coarse body classification. +It includes allowlisted correlation headers only when their values match supported identifier formats. +Unrecognised paths and header values are omitted or redacted. The diagnostic record excludes response bodies, credentials, host names and URL parameters. + +If a poll fails, use its timestamp, operation ID and available correlation IDs to find the API exception and App Service request record. +Check API exception telemetry before a validation run. Record terminal resource deletion separately from the failed poll. +These diagnostics help investigate the failure. They do not establish its cause or guarantee that server telemetry is available. + ## Validate one bundle The [bundle coverage map](https://github.com/microsoft/AzureTRE/blob/main/e2e_tests/bundle_coverage.json) lists every Porter bundle, its prerequisite bundles, exact pytest cases and remaining coverage gaps. diff --git a/e2e_tests/resources/deployment.py b/e2e_tests/resources/deployment.py index 8d5ffb0e8..6189d6374 100644 --- a/e2e_tests/resources/deployment.py +++ b/e2e_tests/resources/deployment.py @@ -1,10 +1,54 @@ import logging +import re +from datetime import datetime, timezone import backoff from httpx import TimeoutException from e2e_tests.helpers import get_auth_header, get_full_endpoint from e2e_tests.resources import strings LOGGER = logging.getLogger(__name__) +_UUID = r"[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}" +_OPERATION_PATH = re.compile( + rf"/api/(?:workspaces/{_UUID}/(?:workspace-services/{_UUID}/(?:user-resources/{_UUID}/)?)?" + rf"|shared-services/{_UUID}/)?operations/{_UUID}" +) +_CORRELATION_HEADERS = { + "x-ms-request-id": _UUID, + "x-ms-correlation-request-id": _UUID, + "x-request-id": _UUID, + "request-id": rf"(?:{_UUID}|\|[0-9a-f]{32}\.[0-9a-f]{16}\.)", + "traceparent": r"00-[0-9a-f]{32}-[0-9a-f]{16}-[0-9a-f]{2}", +} + + +def polling_failure_details(response, operation_endpoint): + """Return bounded metadata. Never copy bodies, URL parameters or arbitrary headers.""" + path = operation_endpoint.split("?", 1)[0].split("#", 1)[0] + media_type = response.headers.get("content-type", "").split(";", 1)[0].strip().lower() + allowed_media_types = {"application/json", "application/problem+json", "text/plain", "text/html"} + prefix = response.content[:64].lstrip().lower() + if not response.content: + body_kind = "empty" + elif prefix.startswith((b"{", b"[")): + body_kind = "json_like" + elif prefix.startswith((b"", + "status": response.status_code, + "content_type": media_type if media_type in allowed_media_types else "other_or_missing", + "body_bytes": len(response.content), + "body_kind": body_kind, + "correlation": { + name: value + for name, pattern in _CORRELATION_HEADERS.items() + if (value := response.headers.get(name, "")) and re.fullmatch(pattern, value) + }, + } async def delete_done(client, operation_endpoint, access_token): @@ -58,8 +102,7 @@ async def check_deployment(client, operation_endpoint, access_token): LOGGER.info(f"Resource not found (404) - treating as deleted: {operation_endpoint}") return strings.RESOURCE_STATUS_DELETED, "Resource has been deleted", "" else: - LOGGER.error(f"Non 200 response in check_deployment: {response.status_code}") - LOGGER.error(f"Full response: {response}") + LOGGER.error("Operation polling failed: %s", polling_failure_details(response, operation_endpoint)) raise Exception("Non 200 response in check_deployment") diff --git a/e2e_tests/unit_tests/test_polling_diagnostics.py b/e2e_tests/unit_tests/test_polling_diagnostics.py new file mode 100644 index 000000000..8451030d0 --- /dev/null +++ b/e2e_tests/unit_tests/test_polling_diagnostics.py @@ -0,0 +1,132 @@ +"""Keep useful HTTP failure evidence without exposing response data or credentials.""" + +import unittest +from unittest.mock import patch + +from httpx import AsyncClient, MockTransport, Response + +from e2e_tests import helpers +from e2e_tests.resources import deployment, strings + + +WORKSPACE = "9f293650-29c7-4291-a074-c5c0aaedd7b7" +OPERATION = "2913b8be-2594-4088-8d93-42a296fe69cc" +REQUEST_ID = "05c22c61-9d22-49d7-b333-65b86a0d70dd" +TRACE = "00-0123456789abcdef0123456789abcdef-0123456789abcdef-01" +ENDPOINT = f"/api/workspaces/{WORKSPACE}/operations/{OPERATION}" + + +class PollingDiagnosticsTests(unittest.IsolatedAsyncioTestCase): + def setUp(self): + self.enterContext(patch.object(helpers.config, "TRE_URL", "https://tre.example.test")) + + async def failure_log(self, response, endpoint=ENDPOINT): + requests = [] + + def handle(request): + requests.append(request) + return response + + with self.assertLogs(deployment.LOGGER, level="ERROR") as logs: + async with AsyncClient(transport=MockTransport(handle)) as client: + with self.assertRaisesRegex(Exception, "Non 200 response in check_deployment"): + await deployment.check_deployment(client, endpoint, "request-token-secret") + self.assertEqual(len(requests), 1, "An HTTP failure must not trigger a retry") + return "\n".join(logs.output) + + async def test_records_utc_time_path_status_and_valid_correlation_ids(self): + log = await self.failure_log( + Response( + 500, + content=b"Internal Server Error", + headers={ + "content-type": "text/plain; charset=utf-8", + "x-ms-request-id": REQUEST_ID, + "traceparent": TRACE, + }, + ) + ) + for value in (ENDPOINT, "500", "GET", "text/plain", REQUEST_ID, TRACE): + self.assertIn(value, log) + self.assertRegex(log, r"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}\+00:00") + self.assertIn("body_bytes", log) + self.assertIn("body_kind", log) + + async def test_excludes_body_query_fragment_credentials_and_arbitrary_headers(self): + secret = "sensitive-payload-secret" + log = await self.failure_log( + Response( + 500, + json={"error": secret}, + headers={ + "set-cookie": secret, + "authorization": secret, + "x-unknown-header": secret, + "x-ms-request-id": secret, + }, + ), + ENDPOINT + "?sig=query-secret#fragment-secret", + ) + self.assertIn(ENDPOINT, log) + for value in (secret, "query-secret", "fragment-secret", "request-token-secret", "tre.example.test"): + self.assertNotIn(value, log) + self.assertIn("json_like", log) + + async def test_suppresses_unknown_paths_and_unbounded_header_values(self): + log = await self.failure_log( + Response( + 500, + content=b"body-secret" * 1000, + headers={ + "content-type": "secret-media-type" * 1000, + "x-ms-correlation-request-id": "a" * 10000, + "request-id": "line-one\nline-two", + "traceparent": "bad-trace-secret", + }, + ), + "/api/operations/path-secret", + ) + self.assertIn("", log) + for value in ("path-secret", "secret-media-type", "line-one", "line-two", "bad-trace-secret", "body-secret"): + self.assertNotIn(value, log) + self.assertLess(len(log), 1200) + + async def test_classifies_response_without_copying_its_content(self): + for content, content_type, expected in ( + (b"", "", "empty"), + (b" failure", "text/html", "html_like"), + (b"[not even valid json", "application/json", "json_like"), + (b"Internal Server Error", "text/plain", "other"), + (b"\x00\xff", "application/octet-stream", "other"), + ): + with self.subTest(expected=expected, content_type=content_type): + log = await self.failure_log(Response(500, content=content, headers={"content-type": content_type})) + self.assertIn(expected, log) + + async def test_other_http_errors_still_fail_once(self): + for code in (400, 401, 403, 429, 503): + with self.subTest(code=code): + log = await self.failure_log(Response(code)) + self.assertIn(str(code), log) + + async def test_workspace_service_and_shared_service_operation_paths_are_retained(self): + for endpoint in ( + f"/api/operations/{OPERATION}", + f"/api/shared-services/{WORKSPACE}/operations/{OPERATION}", + f"/api/workspaces/{WORKSPACE}/workspace-services/{WORKSPACE}/operations/{OPERATION}", + f"/api/workspaces/{WORKSPACE}/workspace-services/{WORKSPACE}/user-resources/{WORKSPACE}/operations/{OPERATION}", + ): + with self.subTest(endpoint=endpoint): + log = await self.failure_log(Response(500), endpoint) + self.assertIn(endpoint, log) + + async def test_success_and_deletion_keep_the_existing_results(self): + for response, expected in ( + (Response(200, json={"operation": {"status": "deleting", "message": "waiting", "steps": []}}), "deleting"), + (Response(404), strings.RESOURCE_STATUS_DELETED), + ): + with self.subTest(expected=expected), patch.object(deployment.LOGGER, "error") as log: + async with AsyncClient(transport=MockTransport(lambda _: response)) as client: + state, _, _ = await deployment.check_deployment(client, ENDPOINT, "token") + self.assertEqual(state, expected) + log.assert_not_called()