From bd9f7f354a412888a35c08d1a8896128ad6c656f Mon Sep 17 00:00:00 2001 From: Nathnael Date: Wed, 12 Aug 2026 09:31:31 +0000 Subject: [PATCH] feat(freight-api): enrich canonical request log line Emit the request line as raw JSON on stdout (level/time/logger as fields) instead of through Nest's console logger, whose prefix made it unparsable. Collect data points via logCtx at the flow chokepoints: BaseRepository writes (status changes, creates, deletes), invoice transitions, payment intent lifecycle + outbound payment-service calls, booking/contract entry state, review-note reasons, signatures and OTP verify outcomes. --- .../src/common/request-log-context.spec.ts | 50 ++++++++++++- .../src/modules/billing/billing.service.ts | 59 ++++++++++++++- .../modules/bookings/bookings.repository.ts | 9 ++- .../src/modules/bookings/bookings.service.ts | 17 ++++- .../contracts/contract-transition.service.ts | 15 +++- .../modules/contracts/contracts.service.ts | 14 +++- .../src/modules/otp/otp.service.ts | 8 ++ .../modules/payment/payment-client.service.ts | 14 ++++ .../src/modules/payment/payment.service.ts | 73 +++++++++++++++++++ .../src/logging/request-log.middleware.ts | 18 ++++- .../src/repositories/base.repository.ts | 32 +++++++- 11 files changed, 295 insertions(+), 14 deletions(-) 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 index 0aefe3695..403b1a137 100644 --- a/apps/edr-freight-api/src/common/request-log-context.spec.ts +++ b/apps/edr-freight-api/src/common/request-log-context.spec.ts @@ -1,5 +1,7 @@ import { Logger } from "@nestjs/common"; +import type { Repository } from "typeorm"; import { + BaseRepository, RequestLogMiddleware, getLogContext, logCtx, @@ -47,10 +49,13 @@ describe("logCtx", () => { describe("RequestLogMiddleware", () => { it("emits one canonical JSON line carrying the collected context", () => { + // Raw stdout, not the Nest logger — the line must be parsable JSON with no + // "[Nest] … LOG [request]" prefix in front of it. const lines: string[] = []; - jest - .spyOn(Logger.prototype, "warn") - .mockImplementation((m) => lines.push(String(m))); + jest.spyOn(process.stdout, "write").mockImplementation((chunk) => { + lines.push(String(chunk)); + return true; + }); jest.spyOn(Logger.prototype, "log").mockImplementation(() => undefined); const listeners: Record void> = {}; @@ -82,7 +87,11 @@ describe("RequestLogMiddleware", () => { listeners.close(); // aborts/close after finish must not double-log expect(lines).toHaveLength(1); + expect(lines[0].endsWith("\n")).toBe(true); + expect(lines[0].startsWith("{")).toBe(true); expect(JSON.parse(lines[0])).toMatchObject({ + level: "warn", + logger: "request", type: "http_request", requestId: "req-42", method: "POST", @@ -100,3 +109,38 @@ describe("RequestLogMiddleware", () => { jest.restoreAllMocks(); }); }); + +describe("BaseRepository write trail", () => { + class TestRepo extends BaseRepository<{ id: string; status?: string }> { + constructor(repo: Repository<{ id: string; status?: string }>) { + super(repo); + } + } + + const typeormRepo = { + metadata: { tableName: "booking" }, + create: (data: unknown) => data, + save: async (data: unknown) => data, + update: async () => undefined, + findOne: async () => ({ id: "b-1", status: "SUBMITTED" }), + softDelete: async () => undefined, + delete: async () => undefined, + } as unknown as Repository<{ id: string; status?: string }>; + + it("records creates, status changes and deletes without any service opting in", async () => { + const ctx = await runWithLogContext({}, async () => { + const repo = new TestRepo(typeormRepo); + await repo.create({ id: "b-1" }); + await repo.update("b-1", { status: "SUBMITTED" }); + await repo.update("b-1", { id: "b-1" }); // no status → no transition entry + await repo.softDelete("b-1"); + return getLogContext(); + }); + + expect(ctx).toEqual({ + db: { created: { booking: 1 }, updated: { booking: 2 } }, + statusChanges: [{ entity: "booking", id: "b-1", status: "SUBMITTED" }], + deleted: [{ entity: "booking", id: "b-1" }], + }); + }); +}); diff --git a/apps/edr-freight-api/src/modules/billing/billing.service.ts b/apps/edr-freight-api/src/modules/billing/billing.service.ts index 9a31466f0..6c7e8455d 100644 --- a/apps/edr-freight-api/src/modules/billing/billing.service.ts +++ b/apps/edr-freight-api/src/modules/billing/billing.service.ts @@ -8,6 +8,7 @@ import { NotFoundException, } from "@nestjs/common"; import { EventEmitter2 } from "@nestjs/event-emitter"; +import { logCtx } from "@edr/api-common"; import { DataSource, EntityManager, In } from "typeorm"; import { Booking } from "../bookings/entities/booking.entity"; @@ -951,6 +952,24 @@ export class BillingService { await mg.update(Invoice, { id: invoice.id }, { status, ...extra }); + // Every invoice status move in the app funnels through here — money + // changing state is the single most-asked question in support. + logCtx( + { + invoiceId: invoice.id, + invoiceNumber: invoice.invoiceNumber, + source: invoice.source, + sourceId: invoice.sourceId, + from: invoice.status, + to: status, + event, + amount: Number(invoice.totalAmount), + currency: invoice.currency, + paymentId: extra.paymentId ?? invoice.paymentId ?? undefined, + }, + { path: "invoiceTransitions", mode: "push" }, + ); + const updated = { ...invoice, ...extra, status } as Invoice; return { result: updated, @@ -1320,6 +1339,21 @@ export class BillingService { throw new BadRequestException("Invoice has no outstanding balance."); } + logCtx( + { + invoiceId: invoice.id, + invoiceNumber: invoice.invoiceNumber, + source: invoice.source, + sourceId: invoice.sourceId, + companyId: invoice.companyId, + amountDue, + currency: invoice.currency, + method: opts.method ?? "TELEBIRR", + platform: opts.platform, + }, + { path: "payment.payInvoice" }, + ); + // CAC Bank is an OTP debit — the bank SMSes the code to this number, so it is // required up front (the payment service rejects it otherwise, as a 502 here). if ( @@ -1443,7 +1477,24 @@ export class BillingService { // first on DESC, which would hand back an unissued invoice. order: { issuedAt: { direction: "DESC", nulls: "LAST" } }, }); - if (!invoice) return null; + if (!invoice) { + logCtx( + { paymentId, outcome: "no-invoice-for-payment" }, + { path: "payment.settleInvoice" }, + ); + return null; + } + + logCtx( + { + paymentId, + providerTxnId, + invoiceId: invoice.id, + invoiceNumber: invoice.invoiceNumber, + invoiceStatus: invoice.status, + }, + { path: "payment.settleInvoice" }, + ); const settleable: Freight.InvoiceStatus[] = [ ...OPEN_STATUSES, @@ -1453,6 +1504,12 @@ export class BillingService { // Already PAID is the ordinary idempotent no-op (redelivery, or settled // inline by payInvoice). Anything else means money was captured with // nowhere to land — that needs a person, so say so loudly. + logCtx( + invoice.status === Freight.InvoiceStatus.Paid + ? "already-paid" + : "captured-with-nowhere-to-land", + { path: "payment.settleInvoice.outcome", mode: "set" }, + ); if (invoice.status !== Freight.InvoiceStatus.Paid) { this.logger.error( `Payment ${paymentId} succeeded but invoice ${invoice.invoiceNumber} ` + diff --git a/apps/edr-freight-api/src/modules/bookings/bookings.repository.ts b/apps/edr-freight-api/src/modules/bookings/bookings.repository.ts index 1c5cc7481..2b1463a95 100644 --- a/apps/edr-freight-api/src/modules/bookings/bookings.repository.ts +++ b/apps/edr-freight-api/src/modules/bookings/bookings.repository.ts @@ -1,4 +1,4 @@ -import { BaseRepository } from '@edr/api-common'; +import { BaseRepository, logCtx } from '@edr/api-common'; import { SchedulingStatus } from '@edr/types'; import { ConflictException, Injectable } from '@nestjs/common'; import { InjectRepository } from '@nestjs/typeorm'; @@ -631,6 +631,13 @@ export class BookingsRepository extends BaseRepository { authorId?: string, ): Promise { const repo = this.dataSource.getRepository(BookingReviewNote); + // Every rejection/cancellation/change-request reason in the booking flow is + // written through here — the "why" behind the status change on the same log + // line as the status change itself. + logCtx( + { bookingId, type, note, authorId }, + { path: 'reviewNotes', mode: 'push' }, + ); return repo.save( repo.create({ bookingId, note, type, authorId: authorId ?? null }), ); diff --git a/apps/edr-freight-api/src/modules/bookings/bookings.service.ts b/apps/edr-freight-api/src/modules/bookings/bookings.service.ts index 121c889bc..6c3f14ecb 100644 --- a/apps/edr-freight-api/src/modules/bookings/bookings.service.ts +++ b/apps/edr-freight-api/src/modules/bookings/bookings.service.ts @@ -9,7 +9,7 @@ import { NotFoundException, } from '@nestjs/common'; import { Freight, SchedulingStatus } from '@edr/types'; -import { insertWithGeneratedReference } from '@edr/api-common'; +import { insertWithGeneratedReference, logCtx } from '@edr/api-common'; // import { CustomersService } from '../customers/customers.service'; import { CompaniesService } from '../companies/companies.service'; import { CompanyKind, CompanyStatus } from '../companies/entities/company.entity'; @@ -2115,6 +2115,21 @@ export class BookingsService { throw new NotFoundException(`Booking ${id} not found`); } + // Nearly every booking flow loads the booking through here, so this one + // call puts the human-searchable reference + entry state on the request log + // line for all of them. Entry state only — the write trail (statusChanges) + // shows where it ended up. + logCtx( + { + id: booking.id, + reference: booking.reference, + statusAtEntry: booking.status, + companyId: booking.companyId, + contractId: booking.contractId ?? undefined, + }, + { path: "booking" }, + ); + if (booking.files && booking.files.length > 0) { booking.files = await Promise.all( booking.files.map(async (file: FileRecord) => { diff --git a/apps/edr-freight-api/src/modules/contracts/contract-transition.service.ts b/apps/edr-freight-api/src/modules/contracts/contract-transition.service.ts index fc3a238ea..e6f208ae2 100644 --- a/apps/edr-freight-api/src/modules/contracts/contract-transition.service.ts +++ b/apps/edr-freight-api/src/modules/contracts/contract-transition.service.ts @@ -9,7 +9,7 @@ import { InjectDataSource } from '@nestjs/typeorm'; import { DataSource } from 'typeorm'; import { randomUUID } from 'node:crypto'; import { Readable } from 'stream'; -import { insertWithGeneratedReference } from '@edr/api-common'; +import { insertWithGeneratedReference, logCtx } from '@edr/api-common'; import type { TCurrentUser } from '@tria-plc/api-common/modules/auth/types/current-user.type'; import { ContractDocumentViewModelBuilder } from '../../contracts/contract-document-view-model.builder'; @@ -1084,6 +1084,19 @@ export class ContractTransitionService { ): Promise { const role = dto.role as ContractSignerRole; + // Both sign() and counterSign() land here — who signed what, and whether the + // ink came from the request or the signer's saved profile signature. + logCtx( + { + contractId: contract.id, + reference: contract.reference, + role, + signerUserId: options.signerUserId, + usedDrawnImage: Boolean(dto.signatureImageBase64), + }, + { path: "contractSignatures", mode: "push" }, + ); + // Resolve the signature image. The client may send a freshly-drawn image, or // omit it to reuse the signer's saved profile signature. Fall back to the // saved one whenever no image is supplied. diff --git a/apps/edr-freight-api/src/modules/contracts/contracts.service.ts b/apps/edr-freight-api/src/modules/contracts/contracts.service.ts index 6e170f126..607a6f525 100644 --- a/apps/edr-freight-api/src/modules/contracts/contracts.service.ts +++ b/apps/edr-freight-api/src/modules/contracts/contracts.service.ts @@ -7,7 +7,7 @@ import { } from '@nestjs/common'; import { InjectDataSource } from '@nestjs/typeorm'; import { DataSource } from 'typeorm'; -import { insertWithGeneratedReference } from '@edr/api-common'; +import { insertWithGeneratedReference, logCtx } from '@edr/api-common'; import { YardCountry } from '@edr/types'; // @@ -811,6 +811,18 @@ export class ContractsService { throw new NotFoundException(`Contract ${id} not found`); } + // Entry state for every contract flow (submit, approve, sign, suspend…) — + // see the equivalent in BookingsService.findById. + logCtx( + { + id: contract.id, + reference: contract.reference, + statusAtEntry: contract.status, + companyId: contract.companyId, + }, + { path: "contract" }, + ); + if (contract.files && contract.files.length > 0) { contract.files = await Promise.all( contract.files.map(async (file: FileRecord) => { diff --git a/apps/edr-freight-api/src/modules/otp/otp.service.ts b/apps/edr-freight-api/src/modules/otp/otp.service.ts index a7361fbdd..42d46226a 100644 --- a/apps/edr-freight-api/src/modules/otp/otp.service.ts +++ b/apps/edr-freight-api/src/modules/otp/otp.service.ts @@ -1,6 +1,7 @@ // otp.service.ts import { BadRequestException, Injectable, Logger } from "@nestjs/common"; +import { logCtx } from "@edr/api-common"; import { randomInt } from "node:crypto"; import { OtpRepository } from "./otp.repository"; @@ -317,6 +318,13 @@ export class OtpService { }`; if (result === "ok") this.logger.log(line); else this.logger.warn(line); + + // Outcome only — the target is a phone number / email address and stays out + // of the canonical line. Channels are safe and say which one was used. + logCtx( + { mode, result, channels: channelsOf(target) }, + { path: "otp.verify", mode: "push" }, + ); } /** diff --git a/apps/edr-freight-api/src/modules/payment/payment-client.service.ts b/apps/edr-freight-api/src/modules/payment/payment-client.service.ts index 26a0cf5ed..de220fd59 100644 --- a/apps/edr-freight-api/src/modules/payment/payment-client.service.ts +++ b/apps/edr-freight-api/src/modules/payment/payment-client.service.ts @@ -7,6 +7,7 @@ import { import { HttpService } from "@nestjs/axios"; import { AxiosError } from "axios"; import { firstValueFrom } from "rxjs"; +import { logCtx } from "@edr/api-common"; import { InitiatePaymentRequest, PaymentIntentSnapshot, @@ -111,6 +112,16 @@ export class PaymentClientService { body?: unknown, ): Promise { const url = `${this.baseUrl}${path}`; + // Every hop to the payment service lands on the request log line: which + // call, how slow, and what it answered. A settle that never happened is + // almost always one of these coming back 4xx/5xx or timing out. + const startedAt = Date.now(); + const trace = (extra: Record) => + logCtx( + { method, path, ms: Date.now() - startedAt, ...extra }, + { path: "outbound.payment", mode: "push" }, + ); + try { const response = await firstValueFrom( this.http.request({ @@ -122,9 +133,11 @@ export class PaymentClientService { : {}, }), ); + trace({ status: response.status }); return response.data; } catch (err) { if (err instanceof AxiosError && err.response) { + trace({ status: err.response.status }); if (err.response.status === 404) throw err; const detail = (err.response.data as { message?: string | string[] })?.message ?? @@ -136,6 +149,7 @@ export class PaymentClientService { } const message = err instanceof Error && err.message ? err.message : String(err); + trace({ unreachable: true, error: message }); this.logger.error( `payment service unreachable (${method} ${path}): ${message}`, ); diff --git a/apps/edr-freight-api/src/modules/payment/payment.service.ts b/apps/edr-freight-api/src/modules/payment/payment.service.ts index 316f3e8fe..4d27c8c77 100644 --- a/apps/edr-freight-api/src/modules/payment/payment.service.ts +++ b/apps/edr-freight-api/src/modules/payment/payment.service.ts @@ -7,6 +7,7 @@ import { Logger, NotFoundException, } from "@nestjs/common"; +import { logCtx } from "@edr/api-common"; import { applyBookingRefDirectionScope } from "../user-trade-access/trade-scope.util"; import { PaymentEntity } from "./entities/payment.entity"; import { PaymentRepository } from "./payment.repository"; @@ -214,8 +215,16 @@ export class PaymentService { PaymentReferenceType.SHIPMENT, referenceId, ); + logCtx( + { referenceId, paid: result.paid, unverifiable: result.unverifiable }, + { path: "payment.reconcile" }, + ); return { paid: result.paid, unverifiable: result.unverifiable }; } catch (err) { + logCtx( + { referenceId, unverifiable: true, error: (err as Error).message }, + { path: "payment.reconcile" }, + ); this.logger.warn( `Reconcile for shipment ${referenceId} failed: ${(err as Error).message}`, ); @@ -224,6 +233,18 @@ export class PaymentService { } async initiate(input: InitiateIntentInput): Promise { + logCtx( + { + referenceId: input.referenceId, + source: input.source, + orderRef: input.orderRef, + method: input.method, + amountMinor: input.amountMinor, + currency: input.currency, + platform: input.platform, + }, + { path: "payment.initiate" }, + ); try { const isCbeBill = input.method === ProviderMethod.CBE_BILL; // CBE settles ETB only (docs/cbe/CBE_IMPLEMENTATION_PLAN.md D8). @@ -268,6 +289,17 @@ export class PaymentService { const intent = await this.upsertIntent(input, snapshot); + logCtx( + { + intentId: intent.id, + providerStatus: snapshot.status, + providerTxnId: snapshot.providerTxnId, + merchantOrderId: snapshot.merchantOrderId, + immediateSuccess, + }, + { path: "payment.initiate" }, + ); + if (immediateSuccess) { // Settle the projection but DO NOT notify billing — billing settles // inline once it has stored intentId on the invoice (see payInvoice), @@ -428,6 +460,17 @@ export class PaymentService { otp, ); + logCtx( + { + intentId: local.id, + refId: local.refId, + gatewayIntentId: snapshot.intentId, + providerStatus: confirmed.status, + failureCode: confirmed.failureCode, + }, + { path: "payment.confirmOtp" }, + ); + if (confirmed.status === ProviderPaymentStatus.SUCCEEDED) { await this.markIntentSucceeded(local.id, { providerTxnId: confirmed.providerTxnId, @@ -460,6 +503,16 @@ export class PaymentService { ): Promise<{ alreadyFinalized: boolean }> { const intent = await this.paymentRepo.findOneBy({ id: intentId }); if (!intent) throw new NotFoundException("PaymentIntent not found"); + logCtx( + { + intentId, + refId: intent.refId, + priorStatus: intent.status, + providerTxnId: opts.providerTxnId, + notifyBilling: opts.notify !== false, + }, + { path: "payment.settle" }, + ); if (intent.status === "success") { // Still notify billing: a prior delivery may have flipped the intent to // success and then died before the invoice settled (the two steps are not @@ -471,6 +524,7 @@ export class PaymentService { opts.paidAt ?? intent.paidAt ?? undefined, ); } + logCtx(true, { path: "payment.settle.alreadyFinalized", mode: "set" }); return { alreadyFinalized: true }; } @@ -507,6 +561,15 @@ export class PaymentService { referenceId: string, ): Promise<{ acknowledged: boolean }> { const intent = await this.paymentRepo.findOneBy({ refId: referenceId }); + logCtx( + { + referenceId, + intentId: intent?.id, + intentStatus: intent?.status ?? "none", + method: intent?.method, + }, + { path: "payment.successRedirect" }, + ); if (!intent || intent.method === "cbe-bill") { return { acknowledged: false }; } @@ -533,6 +596,16 @@ export class PaymentService { }): Promise { const intent = await this.paymentRepo.findOneBy({ id: input.intentId }); if (!intent) throw new NotFoundException("PaymentIntent not found"); + logCtx( + { + intentId: intent.id, + refId: intent.refId, + priorStatus: intent.status, + failureCode: input.failureCode, + failureMessage: input.failureMessage, + }, + { path: "payment.failed" }, + ); if (intent.status === "success" || intent.status === "canceled") return; await this.paymentRepo.update( diff --git a/packages/api-common/src/logging/request-log.middleware.ts b/packages/api-common/src/logging/request-log.middleware.ts index a8067bf02..b25463161 100644 --- a/packages/api-common/src/logging/request-log.middleware.ts +++ b/packages/api-common/src/logging/request-log.middleware.ts @@ -59,7 +59,6 @@ const userId = (req: LoggedRequest): string | undefined => { @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(); @@ -90,6 +89,12 @@ export class RequestLogMiddleware implements NestMiddleware { const line = { ...ctx, + // Fields the Nest console prefix used to carry. They are IN the JSON + // now because this line is written raw (see below) — a log shipper + // needs level and time as parsable fields, not as console decoration. + time: new Date().toISOString(), + level: status >= 500 ? "error" : status >= 400 ? "warn" : "info", + logger: "request", type: "http_request", requestId, method: req.method, @@ -113,6 +118,9 @@ export class RequestLogMiddleware implements NestMiddleware { json = JSON.stringify(line); } catch { json = JSON.stringify({ + time: line.time, + level: line.level, + logger: "request", type: "http_request", requestId, method: req.method, @@ -123,9 +131,11 @@ export class RequestLogMiddleware implements NestMiddleware { }); } - if (status >= 500) this.canonical.error(json); - else if (status >= 400) this.canonical.warn(json); - else this.canonical.log(json); + // Written raw, NOT through Nest's Logger: the console logger wraps every + // message in "[Nest] pid - date LEVEL [ctx] …", which makes the line + // un-parsable as JSON. Same destination the Nest logger writes to + // (stdout, stderr for errors) — only the decoration is dropped. + (status >= 500 ? process.stderr : process.stdout).write(`${json}\n`); }; res.on("finish", emit); diff --git a/packages/api-common/src/repositories/base.repository.ts b/packages/api-common/src/repositories/base.repository.ts index 6374d84a7..c0cc7073b 100644 --- a/packages/api-common/src/repositories/base.repository.ts +++ b/packages/api-common/src/repositories/base.repository.ts @@ -7,9 +7,16 @@ import { Repository, } from "typeorm"; +import { logCtx } from "../logging/request-context"; + export abstract class BaseRepository { protected constructor(protected readonly repository: Repository) {} + /** Table name, for the write trail on the canonical request log line. */ + private get table(): string { + return this.repository.metadata.tableName; + } + /** Find a single entity by its primary key. */ async findById( id: string, @@ -34,22 +41,43 @@ export abstract class BaseRepository { /** Create and persist a new entity. */ async create(data: DeepPartial): Promise { const entity = this.repository.create(data); - return this.repository.save(entity); + const saved = await this.repository.save(entity); + logCtx(1, { path: `db.created.${this.table}`, mode: "count" }); + return saved; } - /** Patch an entity in place and return the reloaded row. */ + /** + * Patch an entity in place and return the reloaded row. + * + * Every domain status machine in this app (booking, contract, wagon, + * warehouse, transfer request…) lands here, so this is the one place that can + * record "what state did this request actually move" without every service + * remembering to log it. + */ async update(id: string, data: DeepPartial): Promise { await this.repository.update(id, data as never); + logCtx(1, { path: `db.updated.${this.table}`, mode: "count" }); + if (data && typeof data === "object" && "status" in data) { + logCtx( + { entity: this.table, id, status: (data as { status: unknown }).status }, + { path: "statusChanges", mode: "push" }, + ); + } return this.findById(id); } /** Soft-delete an entity by primary key (sets deleted_at). */ async softDelete(id: string): Promise { await this.repository.softDelete(id); + logCtx({ entity: this.table, id }, { path: "deleted", mode: "push" }); } /** Permanently delete an entity. Avoid in domain code; prefer softDelete. */ async hardDelete(id: string): Promise { await this.repository.delete(id); + logCtx( + { entity: this.table, id, hard: true }, + { path: "deleted", mode: "push" }, + ); } }