feat(relay): enrich request lifecycle telemetry for retries and outcomes

memory-bank/change-log.md

@@ -1222,3 +1222,44 @@ Validation:
 Follow-ups:
 
 - Optional next iteration: add a PR template block in Azure DevOps mirroring the runbook governance gate checklist.
+
+---
+
+### CL-033: TASK22242 relay telemetry enrichment (lifecycle events + correlation fields)
+
+date: 2026-03-24
+author: Cline
+scope: `pages/api/middleware/relayForwarding.js`, `tests/phase21/relay-forwarding-hardening.test.cjs`
+type: change
+rationale: Add richer relay observability so operations can correlate retries and outcomes per request and track latency/status patterns without changing endpoint contracts.
+impact: Improves operational diagnostics and trend analysis for relay traffic while preserving existing API behavior.
+status: completed
+
+Summary:
+
+- Enriched relay middleware telemetry with request lifecycle events:
+    - `relay_request_started`
+    - `relay_request_retrying`
+    - `relay_request_succeeded`
+    - `relay_request_failed`
+- Added shared telemetry fields for correlation and analysis:
+    - `relayRequestId` (per request correlation id)
+    - `attemptsMade`, `retryCountUsed`, `remainingRetries`
+    - `elapsedMs`
+    - `statusClass` (`2xx/4xx/5xx` style buckets)
+    - resolved runtime knobs included at start event
+- Kept existing retry policy and endpoint response contracts unchanged.
+- Expanded phase21 relay hardening tests to assert telemetry behavior:
+    - started/retrying/succeeded event presence
+    - failed event telemetry fields
+    - stable `relayRequestId` across lifecycle events for one request
+
+Validation:
+
+- `node tests/phase21/relay-forwarding-hardening.test.cjs` -> pass (7/7)
+- `node tests/phase21/endpoint-handler-contract.test.cjs` -> pass (152/152)
+- `npm run lint` -> warnings only (pre-existing `react-hooks/exhaustive-deps`; no new lint errors)
+
+Follow-ups:
+
+- Optional next step: map these lifecycle fields into central dashboards/alerts (retry rate, status-class distribution, p95 elapsedMs).

pages/api/middleware/relayForwarding.js

@@ -109,6 +109,19 @@ const structuredRelayLog = (event, payload) => {
     console.info(event, redactSensitive(payload));
 };
 
+const buildRelayRequestId = () => {
+    return `relay_${Date.now()}_${Math.random().toString(36).slice(2, 10)}`;
+};
+
+const getElapsedMs = (startedAtMs) => {
+    return Math.max(0, Date.now() - startedAtMs);
+};
+
+const getStatusClass = (status) => {
+    if (typeof status !== "number") return "none";
+    return `${Math.floor(status / 100)}xx`;
+};
+
 const shouldRetryRelayError = ({ error, attempt, maxRetries }) => {
     if (attempt >= maxRetries) return false;
 
@@ -226,11 +239,35 @@ export const forwardGetData = async ({
                 : resolvedTimeoutMs
     };
 
+    const relayRequestId = buildRelayRequestId();
+    const startedAtMs = Date.now();
+
+    structuredRelayLog("relay_request_started", {
+        relayRequestId,
+        queryUrl,
+        baseUrl: resolvedBaseUrl,
+        timeoutMs: resolvedTimeoutMs,
+        maxRetries: resolvedMaxRetries,
+        retryBaseDelayMs: resolvedRetryBaseDelayMs,
+        retryMaxDelayMs: resolvedRetryMaxDelayMs
+    });
+
     let lastError;
 
     for (let attempt = 0; attempt <= resolvedMaxRetries; attempt += 1) {
         try {
-            const { data } = await axios.get(finalUrl, axiosOptions);
+            const { data, status } = await axios.get(finalUrl, axiosOptions);
+
+            structuredRelayLog("relay_request_succeeded", {
+                relayRequestId,
+                queryUrl,
+                baseUrl: resolvedBaseUrl,
+                status,
+                statusClass: getStatusClass(status),
+                attemptsMade: attempt + 1,
+                retryCountUsed: attempt,
+                elapsedMs: getElapsedMs(startedAtMs)
+            });
 
             return {
                 data,
@@ -248,13 +285,18 @@ export const forwardGetData = async ({
             if (!retryEligible) {
                 error.__relayAlreadyLogged = true;
                 structuredRelayLog("relay_request_failed", {
+                    relayRequestId,
                     queryUrl,
                     baseUrl: resolvedBaseUrl,
                     attempt: attempt + 1,
                     maxAttempts: resolvedMaxRetries + 1,
+                    attemptsMade: attempt + 1,
+                    retryCountUsed: attempt,
                     status: error?.response?.status,
+                    statusClass: getStatusClass(error?.response?.status),
                     code: error?.code,
-                    message: error?.message
+                    message: error?.message,
+                    elapsedMs: getElapsedMs(startedAtMs)
                 });
                 throw error;
             }
@@ -266,14 +308,20 @@ export const forwardGetData = async ({
             });
 
             structuredRelayLog("relay_request_retrying", {
+                relayRequestId,
                 queryUrl,
                 baseUrl: resolvedBaseUrl,
                 attempt: attempt + 1,
                 maxAttempts: resolvedMaxRetries + 1,
+                attemptsMade: attempt + 1,
+                retryCountUsed: attempt,
+                remainingRetries: resolvedMaxRetries - attempt,
                 delayMs,
                 status: error?.response?.status,
+                statusClass: getStatusClass(error?.response?.status),
                 code: error?.code,
-                message: error?.message
+                message: error?.message,
+                elapsedMs: getElapsedMs(startedAtMs)
             });
 
             await wait(delayMs);

tests/phase21/relay-forwarding-hardening.test.cjs

@@ -43,6 +43,7 @@ const test = (name, fn) => tests.push({ name, fn });
 
 test("forwardGetData retries retryable HTTP status and then succeeds", async () => {
     let callCount = 0;
+    const infoLogs = [];
 
     const mod = loadRelayForwardingModule({
         axios: {
@@ -61,7 +62,13 @@ test("forwardGetData retries retryable HTTP status and then succeeds", async ()
         hashAPIPath: () => "&hash=abc",
         azureHeaders: () => ({ headers: { Authorization: "Bearer token" } }),
         redactSensitive: (value) => value,
-        consoleLogger: () => {}
+        consoleLogger: () => {},
+        console: {
+            log: () => {},
+            info: (...args) => infoLogs.push(args),
+            warn: () => {},
+            error: () => {}
+        }
     });
 
     const result = await mod.forwardGetData({
@@ -74,10 +81,39 @@ test("forwardGetData retries retryable HTTP status and then succeeds", async ()
     assert.strictEqual(callCount, 2);
     assert.deepStrictEqual(result.data, { ok: true });
     assert.strictEqual(result.accessToken, "token");
+
+    const eventNames = infoLogs.map((entry) => entry[0]);
+    assert.ok(eventNames.includes("relay_request_started"));
+    assert.ok(eventNames.includes("relay_request_retrying"));
+    assert.ok(eventNames.includes("relay_request_succeeded"));
+
+    const retryEvent = infoLogs.find(
+        (entry) => entry[0] === "relay_request_retrying"
+    );
+    assert.ok(retryEvent);
+
+    const retryPayload = retryEvent[1];
+    assert.strictEqual(retryPayload.statusClass, "5xx");
+    assert.strictEqual(retryPayload.attemptsMade, 1);
+    assert.strictEqual(retryPayload.retryCountUsed, 0);
+    assert.strictEqual(retryPayload.remainingRetries, 1);
+    assert.ok(typeof retryPayload.relayRequestId === "string");
+
+    const successEvent = infoLogs.find(
+        (entry) => entry[0] === "relay_request_succeeded"
+    );
+    assert.ok(successEvent);
+
+    const successPayload = successEvent[1];
+    assert.strictEqual(successPayload.statusClass, "none");
+    assert.strictEqual(successPayload.attemptsMade, 2);
+    assert.strictEqual(successPayload.retryCountUsed, 1);
+    assert.ok(typeof successPayload.elapsedMs === "number");
 });
 
 test("forwardGetData does not retry non-retryable HTTP status", async () => {
     let callCount = 0;
+    const infoLogs = [];
 
     const mod = loadRelayForwardingModule({
         axios: {
@@ -92,7 +128,13 @@ test("forwardGetData does not retry non-retryable HTTP status", async () => {
         hashAPIPath: () => "&hash=abc",
         azureHeaders: () => ({ headers: {} }),
         redactSensitive: (value) => value,
-        consoleLogger: () => {}
+        consoleLogger: () => {},
+        console: {
+            log: () => {},
+            info: (...args) => infoLogs.push(args),
+            warn: () => {},
+            error: () => {}
+        }
     });
 
     let thrown = null;
@@ -109,6 +151,17 @@ test("forwardGetData does not retry non-retryable HTTP status", async () => {
 
     assert.ok(thrown);
     assert.strictEqual(callCount, 1);
+
+    const failedEvent = infoLogs.find(
+        (entry) => entry[0] === "relay_request_failed"
+    );
+    assert.ok(failedEvent);
+
+    const failedPayload = failedEvent[1];
+    assert.strictEqual(failedPayload.statusClass, "4xx");
+    assert.strictEqual(failedPayload.attemptsMade, 1);
+    assert.strictEqual(failedPayload.retryCountUsed, 0);
+    assert.ok(typeof failedPayload.elapsedMs === "number");
 });
 
 test("forwardGetData does not retry unauthorized status", async () => {
@@ -258,6 +311,64 @@ test("forwardGetData applies timeout and appendHash=false behavior", async () =>
     assert.strictEqual(capturedOptions.headers.Accept, "application/json");
 });
 
+test("forwardGetData telemetry request id is stable across lifecycle events", async () => {
+    const infoLogs = [];
+    let callCount = 0;
+
+    const mod = loadRelayForwardingModule({
+        axios: {
+            get: async () => {
+                callCount += 1;
+                if (callCount === 1) {
+                    const error = new Error("service unavailable");
+                    error.response = { status: 503 };
+                    throw error;
+                }
+
+                return { data: { ok: true }, status: 200 };
+            }
+        },
+        getToken: async () => ({ access_token: "token" }),
+        hashAPIPath: () => "&hash=abc",
+        azureHeaders: () => ({ headers: {} }),
+        redactSensitive: (value) => value,
+        consoleLogger: () => {},
+        console: {
+            log: () => {},
+            info: (...args) => infoLogs.push(args),
+            warn: () => {},
+            error: () => {}
+        }
+    });
+
+    await mod.forwardGetData({
+        queryUrl: "incidents?$top=1",
+        maxRetries: 1,
+        retryBaseDelayMs: 0,
+        retryMaxDelayMs: 0
+    });
+
+    const lifecycleEvents = infoLogs
+        .filter((entry) =>
+            [
+                "relay_request_started",
+                "relay_request_retrying",
+                "relay_request_succeeded"
+            ].includes(entry[0])
+        )
+        .map((entry) => entry[1]);
+
+    assert.strictEqual(lifecycleEvents.length, 3);
+
+    const relayRequestIds = lifecycleEvents.map(
+        (event) => event.relayRequestId
+    );
+    assert.ok(
+        relayRequestIds.every((id) => typeof id === "string" && id.length > 0)
+    );
+    assert.strictEqual(new Set(relayRequestIds).size, 1);
+});
+
 const run = async () => {
     let passed = 0;
     for (const currentTest of tests) {