feat: unify income payment cards and drop period comparisons (WealthLedger/main#33) (#83)

feat: unify income payment cards and drop period comparisons (WealthLedger/main#33)

src/integrations/tbank/tbank.client.spec.ts

@@ -1,5 +1,6 @@
-import { status } from '@grpc/grpc-js';
+import { Metadata, status } from '@grpc/grpc-js';
 import { NotFoundException, ServiceUnavailableException } from '@nestjs/common';
+import { EventEmitter } from 'node:events';
 
 import { TbankOperationState } from './tbank-protocol';
 import { TbankClient } from './tbank.client';
@@ -136,6 +137,68 @@ describe('TbankClient operations', () => {
     );
     jest.useRealTimers();
   });
+
+  it('distinguishes a gRPC deadline from queue delay without logging upstream secrets', async () => {
+    const logger = { event: jest.fn() };
+    const client = Object.assign(Object.create(TbankClient.prototype) as TbankClient, {
+      logger,
+      queue: { size: 0, run: (operation: () => Promise<unknown>) => operation() },
+    });
+    const channel = { getConnectivityState: () => 1 };
+    const service = {
+      getChannel: () => channel,
+      getAccounts: (_input: unknown, _metadata: unknown, _options: unknown, callback: (error: unknown) => void) => {
+        const call = new EventEmitter();
+        void Promise.resolve().then(() => callback({ code: status.DEADLINE_EXCEEDED, details: 'Bearer secret' }));
+        return call;
+      },
+    };
+    const invoke = (client as unknown as { call: (token: string, service: unknown, method: string, input: object) => Promise<unknown> }).call.bind(client);
+    jest.useFakeTimers();
+    try {
+      const failed = invoke('secret', service, 'getAccounts', {});
+      await Promise.all([
+        expect(failed).rejects.toBeInstanceOf(ServiceUnavailableException),
+        jest.advanceTimersByTimeAsync(1000),
+      ]);
+      expect(logger.event).toHaveBeenLastCalledWith('error', 'tbank.rpc.failed', expect.objectContaining({
+        operation: 'getAccounts', grpcCode: status.DEADLINE_EXCEEDED,
+        queueWaitMs: 0, channelState: 'CONNECTING', headersReceived: false,
+      }));
+      expect(JSON.stringify(logger.event.mock.calls)).not.toContain('secret');
+    } finally {
+      jest.useRealTimers();
+    }
+  });
+
+  it('records response headers and a validated upstream tracking ID', async () => {
+    const logger = { event: jest.fn() };
+    const client = Object.assign(Object.create(TbankClient.prototype) as TbankClient, {
+      logger,
+      queue: { size: 0, run: (operation: () => Promise<unknown>) => operation() },
+    });
+    const headers = new Metadata();
+    headers.set('x-tracking-id', '123e4567-e89b-12d3-a456-426614174000');
+    headers.set('authorization', 'Bearer secret');
+    const service = {
+      getChannel: () => ({ getConnectivityState: () => 2 }),
+      getAccounts: (_input: unknown, _metadata: unknown, _options: unknown, callback: (error: null, response: object) => void) => {
+        const call = new EventEmitter();
+        void Promise.resolve().then(() => {
+          call.emit('metadata', headers);
+          callback(null, { accounts: [] });
+        });
+        return call;
+      },
+    };
+    const invoke = (client as unknown as { call: (token: string, service: unknown, method: string, input: object) => Promise<unknown> }).call.bind(client);
+    await expect(invoke('secret', service, 'getAccounts', {})).resolves.toEqual({ accounts: [] });
+    expect(logger.event).toHaveBeenLastCalledWith('debug', 'tbank.rpc.completed', expect.objectContaining({
+      channelState: 'READY', headersReceived: true,
+      trackingId: '123e4567-e89b-12d3-a456-426614174000',
+    }));
+    expect(JSON.stringify(logger.event.mock.calls)).not.toContain('secret');
+  });
 });
 
 describe('TbankClient metadata retries', () => {

src/integrations/tbank/tbank.client.ts

@@ -2,6 +2,7 @@ import {
   ChannelCredentials,
   Client,
   ClientUnaryCall,
+  connectivityState,
   loadPackageDefinition,
   Metadata,
   ServiceError,
@@ -60,6 +61,12 @@ type Unary<Request, Response> = (
   callback: (error: null | ServiceError, response: Response) => void,
 ) => ClientUnaryCall;
 type TbankClientService = Client & Record<string, Unary<never, never>>;
+type RpcDiagnostics = {
+  channelState?: string;
+  headersReceived?: boolean;
+  queueWaitMs?: number;
+  trackingId?: string;
+};
 export type TbankDecimal = { nano?: number | string; units?: number | string };
 export type TbankMoney = TbankDecimal & { currency?: string };
 export type TbankAccount = {
@@ -511,15 +518,20 @@ export class TbankClient {
     for (let attempts = FIRST_ATTEMPT; attempts <= RPC_MAX_ATTEMPTS; attempts += ATTEMPT_INCREMENT) {
       const startedAt = performance.now();
       const queueFull = this.queue.size >= MAX_QUEUE_SIZE;
+      const diagnostics: RpcDiagnostics = {};
       try {
         if (queueFull) {
           throw new ServiceUnavailableException({ code: TbankErrorCode.Unavailable });
         }
-        const response = await this.queue.run(() =>
-          this.request<Response>(token, client, method, request),
-        );
+        const response = await this.queue.run(() => {
+          diagnostics.queueWaitMs = Math.round(performance.now() - startedAt);
+          return this.request<Response>(
+            token, client, method, request, diagnostics,
+          );
+        });
         this.logger.event('debug', 'tbank.rpc.completed', {
           operation: method,
+          ...diagnostics,
           attempts,
           durationMs: Math.round(performance.now() - startedAt),
         });
@@ -537,6 +549,7 @@ export class TbankClient {
         if (retryable && attempts < RPC_MAX_ATTEMPTS) {
           this.logger.event('warn', 'tbank.rpc.retry', {
             operation: method,
+            ...diagnostics,
             ...failureContext,
             attempts,
             durationMs: Math.round(performance.now() - startedAt),
@@ -546,6 +559,7 @@ export class TbankClient {
         }
         this.logger.event('error', 'tbank.rpc.failed', {
           operation: method,
+          ...diagnostics,
           ...failureContext,
           attempts: queueFull ? NO_RPC_ATTEMPTS : attempts,
           durationMs: Math.round(performance.now() - startedAt),
@@ -573,17 +587,42 @@ export class TbankClient {
     client: TbankClientService,
     method: string,
     request: object,
+    diagnostics?: RpcDiagnostics,
   ): Promise<Response> {
     return new Promise((resolve, reject) => {
       const metadata = new Metadata();
       metadata.set('Authorization', `Bearer ${token}`);
+      // A channel state is a snapshot, not proof that this particular call reached the server.
+      const channel = diagnostics && client.getChannel();
+      if (diagnostics) diagnostics.headersReceived = false;
       // eslint-disable-next-line security/detect-object-injection -- Service and method names are internal RPC selections, not request input.
-      client[method](
+      const call = client[method](
         request as never,
         metadata,
         { deadline: new Date(Date.now() + requestDeadlineMs) },
-        (error, response) => (error ? reject(error) : resolve(response)),
+        (error, response) => {
+          if (diagnostics && channel) {
+            diagnostics.channelState = connectivityState[
+              channel.getConnectivityState(false)
+            ];
+          }
+          if (error) reject(error);
+          else resolve(response);
+        },
       );
+      if (diagnostics) {
+        call.on('metadata', (headers: Metadata) => {
+          diagnostics.headersReceived = true;
+          const trackingId = headers.get('x-tracking-id')[0];
+          // Only a UUID may enter logs; never forward arbitrary upstream metadata.
+          if (
+            typeof trackingId === 'string' &&
+            /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i.test(trackingId)
+          ) {
+            diagnostics.trackingId = trackingId;
+          }
+        });
+      }
     });
   }
 }