diff --git a/memory-bank/change-log.md b/memory-bank/change-log.md index 50b7b973..bab663e9 100644 --- a/memory-bank/change-log.md +++ b/memory-bank/change-log.md @@ -1107,3 +1107,85 @@ Validation: Follow-ups: - Batch 12 completes the previously listed remaining P2-S2 relay GET candidates. + +--- + +### CL-030: TASK22236 P2-S3 relay forwarding hardening (timeouts, retries, structured redacted logs) + +date: 2026-03-24 +author: Cline +scope: `pages/api/middleware/relayForwarding.js`, `tests/phase21/relay-forwarding-hardening.test.cjs` +type: change +rationale: Begin P2-S3 by hardening shared relay forwarding behavior with bounded timeout/retry controls and structured redacted operational logging, reducing transient failure impact while preserving endpoint contracts. +impact: Improves resilience/observability for relay GET traffic; endpoint success/error contracts remain unchanged because caller handlers still manage response envelopes. +status: completed + +Summary: + +- Hardened `forwardGetData` in `relayForwarding.js` with: + - configurable timeout (`RELAY_TIMEOUT_MS`, default 8000ms) + - bounded retries (`RELAY_RETRY_MAX`, default 2) + - exponential backoff with cap (`RELAY_RETRY_BASE_DELAY_MS`, `RELAY_RETRY_MAX_DELAY_MS`) + - retry eligibility for transient statuses/codes (`408/429/5xx`, selected network timeout/reset codes) +- Added structured, redacted operational relay logs: + - `relay_request_retrying` + - `relay_request_failed` +- Preserved compatibility behaviors: + - existing token/header/hash handling + - optional `appendHash` and custom `requestOptionsBuilder` + - endpoint-level `relayGet` error response semantics +- Added focused Phase 21 hardening tests: + - retries on retryable status and succeeds + - does not retry non-retryable status + - applies timeout and respects `appendHash=false` + +Validation: + +- `node tests/phase21/relay-forwarding-hardening.test.cjs` -> pass (3/3) +- `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 hardening increment: introduce endpoint-specific retry overrides for write paths (if future non-GET use is introduced) to keep retry policy conservative by operation type. + +--- + +### CL-031: TASK22236 P2-S3 Batch 2A policy tightening (retry classification, config clamping, log de-dup) + +date: 2026-03-24 +author: Cline +scope: `pages/api/middleware/relayForwarding.js`, `tests/phase21/relay-forwarding-hardening.test.cjs` +type: change +rationale: Execute P2-S3 Batch 2A by tightening relay retry policy and operational safety bounds while preventing duplicate error noise between relay-layer and endpoint-layer logging. +impact: Stronger resilience and cleaner observability with no endpoint contract changes; retry behavior is now explicitly conservative for deterministic client/auth failures. +status: completed + +Summary: + +- Updated relay retry policy: + - explicitly non-retryable statuses: `400`, `401`, `403`, `404`, `422` + - retries still allowed for transient classes (`408`, `429`, `5xx`) and selected transport error codes + - any other explicit numeric HTTP status now treated as non-retryable by default +- Added runtime-safe config clamping for relay knobs: + - timeout clamped to `100..30000ms` + - retries clamped to `0..4` + - retry delays clamped to `0..5000ms` + - both env-derived and per-call numeric overrides are sanitized +- Reduced duplicate logging noise: + - non-retry terminal relay failures are marked as already logged in middleware + - `relayGet` catch now skips `consoleLogger` when relay layer has already emitted a structured log +- Expanded relay hardening tests: + - no retry on `401` + - duplicate logging suppression path through `relayGet` + - env-value clamping behavior for timeout bounds + +Validation: + +- `node tests/phase21/relay-forwarding-hardening.test.cjs` -> pass (6/6) +- `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: + +- Batch 2B: update memory/context docs with canonical relay hardening policy, env knobs, and rollback/tuning guidance. diff --git a/memory-bank/decisions.md b/memory-bank/decisions.md index 43fcc8de..e7a676e2 100644 --- a/memory-bank/decisions.md +++ b/memory-bank/decisions.md @@ -45,3 +45,38 @@ Related: - `context/project-overview.md` - `memory-bank/README.md` + +--- + +### D-002: Relay forwarding hardening policy baseline (P2-S3) + +date: 2026-03-24 +author: Cline +scope: `pages/api/middleware/relayForwarding.js`, relay-backed endpoint handlers +type: decision +rationale: Consolidate relay reliability behavior into one shared policy so retries, timeouts, and logging are predictable and safe across all migrated GET flows. +impact: Improves resilience and observability while reducing risk of accidental overload, noisy duplicate logs, and inconsistent retry behavior per endpoint. +status: accepted + +Decision: + +- Shared relay defaults and bounds are centrally enforced in middleware: + - timeout default `8000ms`, clamped to `100..30000ms` + - retries default `2`, clamped to `0..4` + - retry delays clamped to `0..5000ms` +- Retry classification is explicit: + - retryable: `408`, `429`, `5xx`, selected network/transient transport error codes + - non-retryable: deterministic client/auth statuses (`400`, `401`, `403`, `404`, `422`) and other explicit non-retryable HTTP statuses +- Structured relay logs are redacted and emitted once per failure path: + - relay layer emits retry/failure structured events + - endpoint catch logging avoids duplicate emission when relay layer already logged terminal failure + +Consequences: + +- Endpoint contracts remain unchanged while reliability behavior is normalized. +- Future relay policy changes should be made in one location and validated via phase21 hardening tests. + +Related: + +- `memory-bank/change-log.md` (CL-030, CL-031) +- `tests/phase21/relay-forwarding-hardening.test.cjs` diff --git a/memory-bank/patterns.md b/memory-bank/patterns.md index 8734e940..a9a1e288 100644 --- a/memory-bank/patterns.md +++ b/memory-bank/patterns.md @@ -64,3 +64,28 @@ Example paths: - `locales/en/**`, `locales/cy/**` - `next.config.js`, `i18n.js` + +### P-003: Shared Relay Policy via Middleware (No Endpoint Drift) + +date: 2026-03-24 +author: Cline +scope: `pages/api/middleware/relayForwarding.js`, `pages/api/endpoint/*_api.js` relay GET handlers +type: pattern +rationale: Keep reliability and logging policy centralized so endpoint handlers remain thin and behavior stays consistent as relay surface evolves. +impact: Reduces duplication/drift in timeout/retry/error behavior and supports safer incremental endpoint migration/hardening. +status: accepted + +Pattern: +Implement retry/timeout/redacted structured logging in shared relay middleware and keep endpoint handlers focused on validation, transform, and route-level response contracts. + +When to use: + +- Any new or migrated relay-backed endpoint +- Any relay reliability/logging policy update + +Example paths: + +- `pages/api/middleware/relayForwarding.js` +- `pages/api/endpoint/getadvancedsearch_api.js` +- `pages/api/endpoint/getdnscoords_api.js` +- `tests/phase21/relay-forwarding-hardening.test.cjs` diff --git a/memory-bank/techContext.md b/memory-bank/techContext.md index 1913be50..b65a3527 100644 --- a/memory-bank/techContext.md +++ b/memory-bank/techContext.md @@ -22,6 +22,21 @@ - Additional custom server entries exist (`server.js`, `server/server.js`) but are currently treated as non-active for the refactor baseline unless deployment evidence indicates otherwise. - Environment-driven config for auth, relay/API roots, hash key, notify key, and database URL. +### Relay forwarding hardening policy knobs (P2-S3) + +- Shared relay middleware now enforces centralized timeout/retry behavior for relay-backed GET flows. +- Supported env knobs: + - `RELAY_TIMEOUT_MS` (default `8000`, clamped `100..30000`) + - `RELAY_RETRY_MAX` (default `2`, clamped `0..4`) + - `RELAY_RETRY_BASE_DELAY_MS` (default `200`, clamped `0..5000`) + - `RELAY_RETRY_MAX_DELAY_MS` (default `1200`, clamped `0..5000`) +- Retry classification: + - retryable: `408`, `429`, `5xx`, selected transient transport errors + - non-retryable: deterministic client/auth statuses (`400`, `401`, `403`, `404`, `422`) and other explicit non-retryable HTTP statuses +- Logging behavior: + - structured redacted relay events emitted for retry/failure + - duplicate endpoint-layer error logging suppressed when relay layer already emitted terminal failure log + ## Tooling and quality gates - Linting: `npm run lint` (`next lint`). diff --git a/pages/api/middleware/relayForwarding.js b/pages/api/middleware/relayForwarding.js index f5b4c16c..b420186b 100644 --- a/pages/api/middleware/relayForwarding.js +++ b/pages/api/middleware/relayForwarding.js @@ -1,6 +1,6 @@ import axios from "axios"; import { azureHeaders } from "../../../actions/core/headers"; -import { consoleLogger } from "../../../actions/core/logger"; +import { consoleLogger, redactSensitive } from "../../../actions/core/logger"; import { getToken } from "../../../actions/core/token"; import { hashAPIPath } from "../../../actions/core/hash"; import { respondError, respondSuccess } from "./apiResponse"; @@ -9,6 +9,118 @@ const WEBAPI_URL = process.env.RELAY_ROOT || "https://dev-pedw-ns.servicebus.windows.net/dev-pedw-hc/"; +const DEFAULT_TIMEOUT_MS = 8000; +const DEFAULT_MAX_RETRIES = 2; +const DEFAULT_RETRY_BASE_DELAY_MS = 200; +const DEFAULT_RETRY_MAX_DELAY_MS = 1200; +const MAX_TIMEOUT_MS = 30000; +const MAX_RETRIES = 4; +const MAX_RETRY_DELAY_MS = 5000; + +const NON_RETRYABLE_STATUS_CODES = new Set([400, 401, 403, 404, 422]); + +const RETRYABLE_STATUS_CODES = new Set([408, 429, 500, 502, 503, 504]); +const RETRYABLE_ERROR_CODES = new Set([ + "ECONNABORTED", + "ECONNRESET", + "ETIMEDOUT", + "ENOTFOUND", + "EAI_AGAIN", + "EPIPE" +]); + +const parsePositiveInt = (value, fallback) => { + const parsed = Number.parseInt(value, 10); + return Number.isFinite(parsed) && parsed >= 0 ? parsed : fallback; +}; + +const clamp = (value, min, max) => { + return Math.min(max, Math.max(min, value)); +}; + +const sanitizeNumberConfig = ({ + value, + fallback, + min, + max, + allowZero = false +}) => { + const parsed = parsePositiveInt(value, fallback); + const lowerBound = allowZero ? 0 : min; + return clamp(parsed, lowerBound, max); +}; + +const resolveNumericOverride = ({ + overrideValue, + fallbackValue, + min, + max, + allowZero = false +}) => { + if (typeof overrideValue !== "number" || !Number.isFinite(overrideValue)) { + return fallbackValue; + } + + const lowerBound = allowZero ? 0 : min; + return clamp(Math.floor(overrideValue), lowerBound, max); +}; + +const getRelayConfig = () => { + return { + timeoutMs: sanitizeNumberConfig({ + value: process.env.RELAY_TIMEOUT_MS, + fallback: DEFAULT_TIMEOUT_MS, + min: 100, + max: MAX_TIMEOUT_MS + }), + maxRetries: sanitizeNumberConfig({ + value: process.env.RELAY_RETRY_MAX, + fallback: DEFAULT_MAX_RETRIES, + min: 0, + max: MAX_RETRIES, + allowZero: true + }), + retryBaseDelayMs: sanitizeNumberConfig({ + value: process.env.RELAY_RETRY_BASE_DELAY_MS, + fallback: DEFAULT_RETRY_BASE_DELAY_MS, + min: 0, + max: MAX_RETRY_DELAY_MS, + allowZero: true + }), + retryMaxDelayMs: sanitizeNumberConfig({ + value: process.env.RELAY_RETRY_MAX_DELAY_MS, + fallback: DEFAULT_RETRY_MAX_DELAY_MS, + min: 0, + max: MAX_RETRY_DELAY_MS, + allowZero: true + }) + }; +}; + +const backoffDelayMs = ({ attempt, retryBaseDelayMs, retryMaxDelayMs }) => { + return Math.min(retryMaxDelayMs, retryBaseDelayMs * 2 ** attempt); +}; + +const wait = async (delayMs) => { + await new Promise((resolve) => setTimeout(resolve, delayMs)); +}; + +const structuredRelayLog = (event, payload) => { + console.info(event, redactSensitive(payload)); +}; + +const shouldRetryRelayError = ({ error, attempt, maxRetries }) => { + if (attempt >= maxRetries) return false; + + const status = error?.response?.status; + if (NON_RETRYABLE_STATUS_CODES.has(status)) return false; + if (RETRYABLE_STATUS_CODES.has(status)) return true; + if (typeof status === "number") return false; + + const code = error?.code; + return RETRYABLE_ERROR_CODES.has(code); +}; + export const relayGet = async ({ queryUrl, res, @@ -29,7 +141,9 @@ export const relayGet = async ({ : data ); } catch (error) { - consoleLogger(error); + if (!error?.__relayAlreadyLogged) { + consoleLogger(error); + } return respondError(res, errorResponse); } }; @@ -51,8 +165,45 @@ export const forwardGetData = async ({ queryUrl, requestOptionsBuilder, accessToken, - appendHash = true + appendHash = true, + timeoutMs, + maxRetries, + retryBaseDelayMs, + retryMaxDelayMs }) => { + const relayConfig = getRelayConfig(); + + const resolvedTimeoutMs = resolveNumericOverride({ + overrideValue: timeoutMs, + fallbackValue: relayConfig.timeoutMs, + min: 100, + max: MAX_TIMEOUT_MS + }); + + const resolvedMaxRetries = resolveNumericOverride({ + overrideValue: maxRetries, + fallbackValue: relayConfig.maxRetries, + min: 0, + max: MAX_RETRIES, + allowZero: true + }); + + const resolvedRetryBaseDelayMs = resolveNumericOverride({ + overrideValue: retryBaseDelayMs, + fallbackValue: relayConfig.retryBaseDelayMs, + min: 0, + max: MAX_RETRY_DELAY_MS, + allowZero: true + }); + + const resolvedRetryMaxDelayMs = resolveNumericOverride({ + overrideValue: retryMaxDelayMs, + fallbackValue: relayConfig.retryMaxDelayMs, + min: 0, + max: MAX_RETRY_DELAY_MS, + allowZero: true + }); + const tokenAccessToken = typeof accessToken === "string" && accessToken.length > 0 ? accessToken @@ -62,15 +213,72 @@ export const forwardGetData = async ({ const finalUrl = resolvedBaseUrl + queryUrl + (appendHash ? hashAPIPath(queryUrl) : ""); - const { data } = await axios.get( - finalUrl, + const requestOptions = typeof requestOptionsBuilder === "function" ? requestOptionsBuilder(tokenAccessToken) - : azureHeaders(tokenAccessToken) - ); + : azureHeaders(tokenAccessToken); - return { - data, - accessToken: tokenAccessToken + const axiosOptions = { + ...(requestOptions || {}), + timeout: + requestOptions?.timeout != null + ? requestOptions.timeout + : resolvedTimeoutMs }; + + let lastError; + + for (let attempt = 0; attempt <= resolvedMaxRetries; attempt += 1) { + try { + const { data } = await axios.get(finalUrl, axiosOptions); + + return { + data, + accessToken: tokenAccessToken + }; + } catch (error) { + lastError = error; + + const retryEligible = shouldRetryRelayError({ + error, + attempt, + maxRetries: resolvedMaxRetries + }); + + if (!retryEligible) { + error.__relayAlreadyLogged = true; + structuredRelayLog("relay_request_failed", { + queryUrl, + baseUrl: resolvedBaseUrl, + attempt: attempt + 1, + maxAttempts: resolvedMaxRetries + 1, + status: error?.response?.status, + code: error?.code, + message: error?.message + }); + throw error; + } + + const delayMs = backoffDelayMs({ + attempt, + retryBaseDelayMs: resolvedRetryBaseDelayMs, + retryMaxDelayMs: resolvedRetryMaxDelayMs + }); + + structuredRelayLog("relay_request_retrying", { + queryUrl, + baseUrl: resolvedBaseUrl, + attempt: attempt + 1, + maxAttempts: resolvedMaxRetries + 1, + delayMs, + status: error?.response?.status, + code: error?.code, + message: error?.message + }); + + await wait(delayMs); + } + } + + throw lastError; }; diff --git a/tests/phase21/relay-forwarding-hardening.test.cjs b/tests/phase21/relay-forwarding-hardening.test.cjs new file mode 100644 index 00000000..fd238806 --- /dev/null +++ b/tests/phase21/relay-forwarding-hardening.test.cjs @@ -0,0 +1,279 @@ +const assert = require("assert"); +const fs = require("fs"); +const path = require("path"); +const vm = require("vm"); + +const rootDir = path.resolve(__dirname, "..", ".."); + +const loadRelayForwardingModule = (injected = {}) => { + const filePath = path.join( + rootDir, + "pages/api/middleware/relayForwarding.js" + ); + let source = fs.readFileSync(filePath, "utf8"); + + source = source.replace(/import[\s\S]*?from\s+"[^"]+";\n?/g, ""); + source = source.replace(/export const\s+/g, "const "); + + source += + "\nmodule.exports = { relayGet, relayGetData, forwardGetData };\n"; + + const context = { + module: { exports: {} }, + exports: {}, + require, + process, + setTimeout, + clearTimeout, + console: { + log: () => {}, + info: () => {}, + warn: () => {}, + error: () => {} + }, + ...injected + }; + + vm.runInNewContext(source, context, { filename: filePath }); + return context.module.exports; +}; + +const tests = []; +const test = (name, fn) => tests.push({ name, fn }); + +test("forwardGetData retries retryable HTTP status and then succeeds", async () => { + let callCount = 0; + + const mod = loadRelayForwardingModule({ + axios: { + get: async () => { + callCount += 1; + if (callCount === 1) { + const error = new Error("temporary outage"); + error.response = { status: 503 }; + throw error; + } + + return { data: { ok: true } }; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: { Authorization: "Bearer token" } }), + redactSensitive: (value) => value, + consoleLogger: () => {} + }); + + const result = await mod.forwardGetData({ + queryUrl: "incidents?$top=1", + maxRetries: 1, + retryBaseDelayMs: 0, + retryMaxDelayMs: 0 + }); + + assert.strictEqual(callCount, 2); + assert.deepStrictEqual(result.data, { ok: true }); + assert.strictEqual(result.accessToken, "token"); +}); + +test("forwardGetData does not retry non-retryable HTTP status", async () => { + let callCount = 0; + + const mod = loadRelayForwardingModule({ + axios: { + get: async () => { + callCount += 1; + const error = new Error("bad request"); + error.response = { status: 400 }; + throw error; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: {} }), + redactSensitive: (value) => value, + consoleLogger: () => {} + }); + + let thrown = null; + try { + await mod.forwardGetData({ + queryUrl: "incidents?$top=1", + maxRetries: 3, + retryBaseDelayMs: 0, + retryMaxDelayMs: 0 + }); + } catch (error) { + thrown = error; + } + + assert.ok(thrown); + assert.strictEqual(callCount, 1); +}); + +test("forwardGetData does not retry unauthorized status", async () => { + let callCount = 0; + + const mod = loadRelayForwardingModule({ + axios: { + get: async () => { + callCount += 1; + const error = new Error("unauthorized"); + error.response = { status: 401 }; + throw error; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: {} }), + redactSensitive: (value) => value, + consoleLogger: () => {} + }); + + let thrown = null; + try { + await mod.forwardGetData({ + queryUrl: "incidents?$top=1", + maxRetries: 3, + retryBaseDelayMs: 0, + retryMaxDelayMs: 0 + }); + } catch (error) { + thrown = error; + } + + assert.ok(thrown); + assert.strictEqual(callCount, 1); +}); + +test("relayGet avoids duplicate consoleLogger when relay layer already logged", async () => { + let consoleLoggerCalls = 0; + let respondErrorCalls = 0; + + const mod = loadRelayForwardingModule({ + axios: { + get: async () => { + const error = new Error("bad request"); + error.response = { status: 400 }; + throw error; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: {} }), + redactSensitive: (value) => value, + consoleLogger: () => { + consoleLoggerCalls += 1; + }, + respondSuccess: () => {}, + respondError: () => { + respondErrorCalls += 1; + } + }); + + await mod.relayGet({ + queryUrl: "incidents?$top=1", + res: {}, + errorResponse: { code: "FAILED" } + }); + + assert.strictEqual(consoleLoggerCalls, 0); + assert.strictEqual(respondErrorCalls, 1); +}); + +test("forwardGetData clamps invalid env config values to safe bounds", async () => { + const previousEnv = { + RELAY_TIMEOUT_MS: process.env.RELAY_TIMEOUT_MS, + RELAY_RETRY_MAX: process.env.RELAY_RETRY_MAX, + RELAY_RETRY_BASE_DELAY_MS: process.env.RELAY_RETRY_BASE_DELAY_MS, + RELAY_RETRY_MAX_DELAY_MS: process.env.RELAY_RETRY_MAX_DELAY_MS + }; + + process.env.RELAY_TIMEOUT_MS = "999999"; + process.env.RELAY_RETRY_MAX = "999"; + process.env.RELAY_RETRY_BASE_DELAY_MS = "-1"; + process.env.RELAY_RETRY_MAX_DELAY_MS = "999999"; + + let capturedOptions = null; + + const mod = loadRelayForwardingModule({ + axios: { + get: async (url, options) => { + capturedOptions = options; + return { data: { ok: true } }; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: {} }), + redactSensitive: (value) => value, + consoleLogger: () => {} + }); + + await mod.forwardGetData({ + queryUrl: "incidents?$top=1" + }); + + assert.strictEqual(capturedOptions.timeout, 30000); + + process.env.RELAY_TIMEOUT_MS = previousEnv.RELAY_TIMEOUT_MS; + process.env.RELAY_RETRY_MAX = previousEnv.RELAY_RETRY_MAX; + process.env.RELAY_RETRY_BASE_DELAY_MS = + previousEnv.RELAY_RETRY_BASE_DELAY_MS; + process.env.RELAY_RETRY_MAX_DELAY_MS = previousEnv.RELAY_RETRY_MAX_DELAY_MS; +}); + +test("forwardGetData applies timeout and appendHash=false behavior", async () => { + let capturedUrl = null; + let capturedOptions = null; + + const mod = loadRelayForwardingModule({ + axios: { + get: async (url, options) => { + capturedUrl = url; + capturedOptions = options; + return { data: { ok: true } }; + } + }, + getToken: async () => ({ access_token: "token" }), + hashAPIPath: () => "&hash=abc", + azureHeaders: () => ({ headers: { Accept: "application/json" } }), + redactSensitive: (value) => value, + consoleLogger: () => {} + }); + + await mod.forwardGetData({ + baseUrl: "http://localhost:3000", + queryUrl: "/api/endpoint/example", + appendHash: false, + timeoutMs: 1234, + maxRetries: 0 + }); + + assert.strictEqual( + capturedUrl, + "http://localhost:3000/api/endpoint/example" + ); + assert.strictEqual(capturedOptions.timeout, 1234); + assert.strictEqual(capturedOptions.headers.Accept, "application/json"); +}); + +const run = async () => { + let passed = 0; + for (const currentTest of tests) { + await currentTest.fn(); + passed += 1; + } + console.log( + `Phase 21 relay-forwarding hardening tests passed (${passed}/${tests.length}).` + ); +}; + +module.exports = run; + +if (require.main === module) { + run().catch((error) => { + console.error(error); + process.exit(1); + }); +}