diff --git a/apps/edr-freight-api/src/app.module.ts b/apps/edr-freight-api/src/app.module.ts index 029f2040b..bb7a3b9fd 100644 --- a/apps/edr-freight-api/src/app.module.ts +++ b/apps/edr-freight-api/src/app.module.ts @@ -114,7 +114,7 @@ import { InterchangeDocumentsModule } from "./modules/interchange-documents/inte import { ImportOperationsModule } from "./modules/import-operations/import-operations.module"; import { AiModule } from "./modules/ai/ai.module"; import { AuditModule } from "./modules/audit/audit.module"; -import { LoggerMiddleware } from "./logger.middleware"; +import { RequestLogMiddleware } from "@edr/api-common"; import { LoginAudienceMiddleware } from "./modules/auth/login-audience.middleware"; import { PositionTypePermissionsCache } from "./common/position-type-permissions.cache"; @@ -392,7 +392,9 @@ export class AppModule implements OnApplicationBootstrap { } configure(consumer: MiddlewareConsumer) { - consumer.apply(LoggerMiddleware).forRoutes("*"); + // FIRST: opens the request log context every later middleware/guard/service + // writes into via logCtx(). Anything applied above it logs into the void. + consumer.apply(RequestLogMiddleware).forRoutes("*"); consumer .apply(LoginAudienceMiddleware) .forRoutes( diff --git a/apps/edr-freight-api/src/common/request-log-context.spec.ts b/apps/edr-freight-api/src/common/request-log-context.spec.ts new file mode 100644 index 000000000..0aefe3695 --- /dev/null +++ b/apps/edr-freight-api/src/common/request-log-context.spec.ts @@ -0,0 +1,102 @@ +import { Logger } from "@nestjs/common"; +import { + RequestLogMiddleware, + getLogContext, + logCtx, + runWithLogContext, +} from "@edr/api-common"; + +describe("logCtx", () => { + it("is a no-op outside a request", () => { + expect(() => logCtx({ bookingId: "b1" })).not.toThrow(); + expect(getLogContext()).toBeUndefined(); + }); + + it("collects data points across the request and isolates concurrent ones", async () => { + const collect = async (id: string) => + runWithLogContext({ requestId: id }, async () => { + logCtx({ bookingId: id }); + await Promise.resolve(); + logCtx({ from: "DRAFT", to: "SUBMITTED" }, { path: "booking.status" }); + logCtx({ wagonId: "w1" }, { path: "wagons", mode: "push" }); + logCtx({ wagonId: "w2" }, { path: "wagons", mode: "push" }); + logCtx(1, { path: "smsSent", mode: "count" }); + logCtx(1, { path: "smsSent", mode: "count" }); + logCtx("PAID", { path: "payment.state", mode: "set" }); + logCtx({ ignored: true }, (ctx) => { + ctx.custom = "yes"; + }); + return getLogContext(); + }); + + const [a, b] = await Promise.all([collect("r1"), collect("r2")]); + + expect(a).toEqual({ + requestId: "r1", + bookingId: "r1", + booking: { status: { from: "DRAFT", to: "SUBMITTED" } }, + wagons: [{ wagonId: "w1" }, { wagonId: "w2" }], + smsSent: 2, + payment: { state: "PAID" }, + custom: "yes", + }); + expect(b?.requestId).toBe("r2"); + expect(b?.bookingId).toBe("r2"); + }); +}); + +describe("RequestLogMiddleware", () => { + it("emits one canonical JSON line carrying the collected context", () => { + const lines: string[] = []; + jest + .spyOn(Logger.prototype, "warn") + .mockImplementation((m) => lines.push(String(m))); + jest.spyOn(Logger.prototype, "log").mockImplementation(() => undefined); + + const listeners: Record void> = {}; + const req = { + method: "POST", + url: "/api/bookings/1/submit", + originalUrl: "/api/bookings/1/submit?dry=1", + baseUrl: "/api/bookings", + route: { path: "/:id/submit" }, + headers: { "user-agent": "jest", "x-request-id": "req-42" }, + ip: "10.0.0.1", + query: { dry: "1" }, + user: { id: "u-7" }, + }; + const res = { + statusCode: 409, + writableEnded: true, + setHeader: jest.fn(), + on: (event: string, fn: () => void) => { + listeners[event] = fn; + }, + }; + + new RequestLogMiddleware().use(req, res, () => { + logCtx({ bookingId: "b-1" }); + logCtx("REJECTED", { path: "booking.outcome", mode: "set" }); + }); + listeners.finish(); + listeners.close(); // aborts/close after finish must not double-log + + expect(lines).toHaveLength(1); + expect(JSON.parse(lines[0])).toMatchObject({ + type: "http_request", + requestId: "req-42", + method: "POST", + route: "/api/bookings/:id/submit", + url: "/api/bookings/1/submit?dry=1", + status: 409, + userId: "u-7", + ip: "10.0.0.1", + userAgent: "jest", + query: { dry: "1" }, + bookingId: "b-1", + booking: { outcome: "REJECTED" }, + }); + expect(res.setHeader).toHaveBeenCalledWith("x-request-id", "req-42"); + jest.restoreAllMocks(); + }); +}); diff --git a/apps/edr-freight-api/src/logger.middleware.ts b/apps/edr-freight-api/src/logger.middleware.ts deleted file mode 100644 index dd7532ec8..000000000 --- a/apps/edr-freight-api/src/logger.middleware.ts +++ /dev/null @@ -1,21 +0,0 @@ -import { Injectable, NestMiddleware, Logger } from "@nestjs/common"; -import { Request, Response, NextFunction } from "express"; - -@Injectable() -export class LoggerMiddleware implements NestMiddleware { - private readonly logger = new Logger("HTTP"); - - use(req: Request, res: Response, next: NextFunction) { - const start = Date.now(); - - res.on("finish", () => { - const duration = Date.now() - start; - - this.logger.log( - `${req.method} ${req.originalUrl} ${res.statusCode} ${duration}ms`, - ); - }); - - next(); - } -} diff --git a/apps/edr-freight-api/src/modules/companies/services/etrade-business-selection.spec.ts b/apps/edr-freight-api/src/modules/companies/services/etrade-business-selection.spec.ts index 0719d7fe8..86117d306 100644 --- a/apps/edr-freight-api/src/modules/companies/services/etrade-business-selection.spec.ts +++ b/apps/edr-freight-api/src/modules/companies/services/etrade-business-selection.spec.ts @@ -63,6 +63,21 @@ describe('ETradeService business selection', () => { expect(fetched).toEqual(['MT/AA/14/670/11551235/2017']); }); + it('survives the null entries eTrade puts in SubGroups', () => { + const { service } = build(); + const info = companyInfo(); + (info.Businesses[0] as any).SubGroups = [ + null, + { Code: 66331, Description: 'Export trade in minerals' }, + { Code: 1, Description: null }, + ]; + const data = service.extractRegistrationData( + { LicenceNumber: 'x' } as ETradeBusinessInfo, + info, + ); + expect(data.businesses?.[0].activity).toBe('Export trade in minerals'); + }); + it('lists every licence for the picker, code prefixes stripped', () => { const { service } = build(); const data = service.extractRegistrationData( diff --git a/apps/edr-freight-api/src/modules/companies/services/etrade.service.ts b/apps/edr-freight-api/src/modules/companies/services/etrade.service.ts index 45cc8e840..fac57238a 100644 --- a/apps/edr-freight-api/src/modules/companies/services/etrade.service.ts +++ b/apps/edr-freight-api/src/modules/companies/services/etrade.service.ts @@ -142,7 +142,8 @@ export class ETradeService { tradeName: b.TradesName?.trim() || "", activity: (b.SubGroups ?? []) // Some descriptions repeat the code inline ("(65611)Import trade …"). - .map((g) => g.Description?.replace(/^\(\d+\)\s*/, "").trim()) + // eTrade also puts null entries in this array, so every hop is optional. + .map((g) => g?.Description?.replace(/^\(\d+\)\s*/, "").trim()) .filter(Boolean) .join(", "), renewedTo: b.RenewedTo || "", diff --git a/apps/edr-freight-web/backoffice/src/complaints/services/etradeTinService.ts b/apps/edr-freight-web/backoffice/src/complaints/services/etradeTinService.ts index 3bdc653c4..8feb7cfb8 100644 --- a/apps/edr-freight-web/backoffice/src/complaints/services/etradeTinService.ts +++ b/apps/edr-freight-web/backoffice/src/complaints/services/etradeTinService.ts @@ -101,7 +101,8 @@ export function mapEtradeBusinessLicenses( const tradeName = String(business.TradesName ?? "").trim(); const tradeNameAmh = String(business.TradeNameAmh ?? "").trim(); const activities = (business.SubGroups ?? []) - .map((group) => String(group.Description ?? "").trim()) + // eTrade returns null entries in this array, not just a null array. + .map((group) => String(group?.Description ?? "").trim()) .filter(Boolean); const displayTradeName = diff --git a/packages/api-common/src/filters/http-exception.filter.ts b/packages/api-common/src/filters/http-exception.filter.ts index 3dc301a0b..3015d239f 100644 --- a/packages/api-common/src/filters/http-exception.filter.ts +++ b/packages/api-common/src/filters/http-exception.filter.ts @@ -7,6 +7,8 @@ import { Logger, } from "@nestjs/common"; +import { logCtx } from "../logging/request-context"; + interface ErrorResponseBody { success: false; statusCode: number; @@ -120,6 +122,18 @@ export class HttpExceptionFilter implements ExceptionFilter { path: request.url, }; + // Land the failure on the request's canonical log line too — the middleware + // only sees a status code, not what threw. No-op outside a request. + logCtx( + { + name: exception instanceof Error ? exception.name : "Error", + message, + status, + stack: status >= 500 ? (exception as Error)?.stack : undefined, + }, + { path: "error", mode: "set" }, + ); + if (status >= 500) { this.logger.error( `${request.method} ${request.url} -> ${status}`, diff --git a/packages/api-common/src/index.ts b/packages/api-common/src/index.ts index 8561f3721..d71f026da 100644 --- a/packages/api-common/src/index.ts +++ b/packages/api-common/src/index.ts @@ -6,6 +6,10 @@ export * from "./decorators/public.decorator"; // Filters export * from "./filters/http-exception.filter"; +// Logging +export * from "./logging/request-context"; +export * from "./logging/request-log.middleware"; + // Interceptors export * from "./interceptors/response-transform.interceptor"; diff --git a/packages/api-common/src/logging/request-context.ts b/packages/api-common/src/logging/request-context.ts new file mode 100644 index 000000000..0b41222ee --- /dev/null +++ b/packages/api-common/src/logging/request-context.ts @@ -0,0 +1,109 @@ +import { AsyncLocalStorage } from "node:async_hooks"; + +/** + * Per-request bag of data points that end up on the canonical request log line + * (see request-log.middleware.ts). Anything written here is flattened into one + * JSON object at the end of the request, so keep it to values that are safe to + * ship to a log aggregator: ids, states, counts, outcomes — never secrets, + * tokens, or raw uploads. + */ +export type RequestLogContext = Record; + +const storage = new AsyncLocalStorage(); + +export const getLogContext = (): RequestLogContext | undefined => + storage.getStore(); + +export const runWithLogContext = ( + seed: RequestLogContext, + fn: () => T, +): T => storage.run(seed, fn); + +export interface LogCtxOptions { + /** + * Dot path to write under, e.g. "booking.transition". Namespacing is just a + * path with one segment ("payment"). Root object when omitted. + */ + path?: string; + /** + * How the value lands: + * - `merge` (default) — shallow-merge objects into the target + * - `set` — overwrite the target + * - `push` — append to an array at the target + * - `count` — add the value (default 1) to a numeric counter at the target + */ + mode?: "merge" | "set" | "push" | "count"; +} + +/** Escape hatch when the four modes don't fit: mutate the context yourself. */ +export type LogCtxMutator = (ctx: RequestLogContext, value: unknown) => void; + +// ponytail: fixed cap so a loop calling logCtx in `push` mode can't grow an +// unbounded array in memory / a megabyte log line. Per-path caps if one ever +// legitimately needs more. +const MAX_PUSHED = 100; + +const isPlainObject = (v: unknown): v is Record => + typeof v === "object" && v !== null && !Array.isArray(v); + +/** + * Append a data point to the current request's canonical log line. + * + * No-op outside an HTTP request (bootstrap, cron, queue consumers) — callers + * never need to guard. + * + * logCtx({ bookingId, status }); // root merge + * logCtx(intentId, { path: "payment.intentId", mode: "set" }); + * logCtx({ from, to }, { path: "booking.transition" }); // namespaced + * logCtx({ wagonId }, { path: "wagons", mode: "push" }); // array + * logCtx(1, { path: "smsSent", mode: "count" }); // counter + * logCtx(err, (ctx, e) => { ctx.lastError = String(e); }); // custom + */ +export function logCtx( + value: unknown, + opts: LogCtxOptions | LogCtxMutator = {}, +): void { + const ctx = storage.getStore(); + if (!ctx) return; + + if (typeof opts === "function") { + opts(ctx, value); + return; + } + + const { path, mode = "merge" } = opts; + + if (!path) { + if (isPlainObject(value)) Object.assign(ctx, value); + return; + } + + const keys = path.split("."); + const leaf = keys.pop() as string; + let node: Record = ctx; + for (const key of keys) { + if (!isPlainObject(node[key])) node[key] = {}; + node = node[key] as Record; + } + + switch (mode) { + case "set": + node[leaf] = value; + break; + case "push": { + const arr = Array.isArray(node[leaf]) ? (node[leaf] as unknown[]) : []; + if (arr.length < MAX_PUSHED) arr.push(value); + node[leaf] = arr; + break; + } + case "count": + node[leaf] = + ((node[leaf] as number) ?? 0) + (typeof value === "number" ? value : 1); + break; + default: + node[leaf] = + isPlainObject(node[leaf]) && isPlainObject(value) + ? Object.assign(node[leaf] as Record, value) + : value; + } +} diff --git a/packages/api-common/src/logging/request-log.middleware.ts b/packages/api-common/src/logging/request-log.middleware.ts new file mode 100644 index 000000000..a8067bf02 --- /dev/null +++ b/packages/api-common/src/logging/request-log.middleware.ts @@ -0,0 +1,137 @@ +import { randomUUID } from "node:crypto"; +import { Injectable, Logger, NestMiddleware } from "@nestjs/common"; + +import { + RequestLogContext, + logCtx, + runWithLogContext, +} from "./request-context"; + +/** + * Structural request/response shapes — express types are not a dependency of + * this package (they arrive under @nestjs/platform-express in the apps). + */ +interface LoggedRequest { + method: string; + url: string; + originalUrl?: string; + baseUrl?: string; + route?: { path?: string }; + headers: Record; + ip?: string; + query?: Record; + user?: Record | null; +} + +interface LoggedResponse { + statusCode: number; + writableEnded?: boolean; + setHeader(name: string, value: string): void; + on(event: string, listener: () => void): void; +} + +const header = (req: LoggedRequest, name: string): string | undefined => { + const value = req.headers[name]; + return Array.isArray(value) ? value[0] : value; +}; + +const userId = (req: LoggedRequest): string | undefined => { + const user = req.user; + if (!user) return undefined; + const id = user.id ?? user.sub ?? user.userId; + return typeof id === "string" || typeof id === "number" + ? String(id) + : undefined; +}; + +/** + * Opens an AsyncLocalStorage context for the request (so anything downstream + * can `logCtx(...)` into it) and emits ONE canonical JSON line per request when + * the response ends — request metadata plus every data point collected during + * the flow, on the same Nest logger transport as the rest of the app. + * + * Base fields win over collected context on key collisions, so a stray + * `logCtx({ status })` can never corrupt the fields dashboards filter on. + * + * Apply FIRST in `configure()`: middleware registered before this one runs + * outside the context and its `logCtx` calls are silently dropped. + */ +@Injectable() +export class RequestLogMiddleware implements NestMiddleware { + private readonly logger = new Logger("HTTP"); + private readonly canonical = new Logger("request"); + + use(req: LoggedRequest, res: LoggedResponse, next: () => void): void { + const start = Date.now(); + const requestId = header(req, "x-request-id") ?? randomUUID(); + res.setHeader("x-request-id", requestId); + + // Held by reference, NOT read back through the ALS at emit time: response + // "finish"/"close" listeners are plain EventEmitter callbacks, which Node + // does not bind to the async context they were registered in — getStore() + // there returns whatever context happened to call res.end(). + const ctx: RequestLogContext = {}; + + runWithLogContext(ctx, () => { + logCtx({ requestId }); + + let emitted = false; + // "finish" covers normal responses; "close" catches client aborts, where + // "finish" never fires and the request would vanish from the logs. + const emit = () => { + if (emitted) return; + emitted = true; + + const url = req.originalUrl ?? req.url; + const status = res.statusCode; + const durationMs = Date.now() - start; + + this.logger.log(`${req.method} ${url} ${status} ${durationMs}ms`); + + const line = { + ...ctx, + type: "http_request", + requestId, + method: req.method, + route: req.route?.path + ? `${req.baseUrl ?? ""}${req.route.path}` + : undefined, + url, + status, + durationMs, + userId: userId(req), + ip: req.ip, + userAgent: header(req, "user-agent"), + query: + req.query && Object.keys(req.query).length ? req.query : undefined, + aborted: res.writableEnded === false ? true : undefined, + }; + // A circular value pushed into the context must not throw inside a + // response listener — that would take the process down, not the log. + let json: string; + try { + json = JSON.stringify(line); + } catch { + json = JSON.stringify({ + type: "http_request", + requestId, + method: req.method, + url, + status, + durationMs, + contextSerializationFailed: true, + }); + } + + if (status >= 500) this.canonical.error(json); + else if (status >= 400) this.canonical.warn(json); + else this.canonical.log(json); + }; + + res.on("finish", emit); + res.on("close", emit); + + next(); + }); + } +} diff --git a/packages/types/src/freight/etrade.ts b/packages/types/src/freight/etrade.ts index 6f33567e4..c23492413 100644 --- a/packages/types/src/freight/etrade.ts +++ b/packages/types/src/freight/etrade.ts @@ -55,7 +55,8 @@ export interface ETradeCompanyInfo { RenewedFrom: string; RenewedTo: string; BusinessLicensingGroupMain: string | null; - SubGroups: Array<{ Code: number; Description: string }> | null; + /** eTrade returns null entries in this array as well as a null array. */ + SubGroups: Array<{ Code: number; Description: string | null } | null> | null; }>; }