diff --git a/memory-bank/change-log.md b/memory-bank/change-log.md index 097f10da..7fc31800 100644 --- a/memory-bank/change-log.md +++ b/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). diff --git a/pages/api/middleware/relayForwarding.js b/pages/api/middleware/relayForwarding.js index b420186b..55371577 100644 --- a/pages/api/middleware/relayForwarding.js +++ b/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); diff --git a/tests/phase21/relay-forwarding-hardening.test.cjs b/tests/phase21/relay-forwarding-hardening.test.cjs index fd238806..1b0ff9ad 100644 --- a/tests/phase21/relay-forwarding-hardening.test.cjs +++ b/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) {