Record safe diagnostics for failed operation polls

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))

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.

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"<!doctype html", b"<html")):
+        body_kind = "html_like"
+    else:
+        body_kind = "other"
+    return {
+        "utc_time": datetime.now(timezone.utc).isoformat(timespec="milliseconds"),
+        "method": "GET",
+        "path": path if _OPERATION_PATH.fullmatch(path) else "<redacted>",
+        "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")
 
 

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("<redacted>", 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"  <!DOCTYPE html><html>failure</html>", "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()