feat: add logging

src/tbank/brokerage-operations.service.spec.ts

@@ -19,10 +19,12 @@ describe('BrokerageOperationsService', () => {
     getOpenAccounts: jest.fn(),
     getOperationsByCursor: jest.fn(),
   };
+  const requestContext = { set: jest.fn() };
   const service = new BrokerageOperationsService(
     prisma as never,
     config as never,
     tbank as never,
+    requestContext as never,
   );
   const crypto = TbankCrypto.fromBase64(key);
   let operationsRequest: unknown;

src/tbank/brokerage-operations.service.ts

@@ -5,6 +5,7 @@ import {
   NotFoundException,
 } from '@nestjs/common';
 import { ConfigService } from '@nestjs/config';
+import { RequestContextService } from '../common/logging/request-context.service';
 import { Environment } from '../config/env.validation';
 import { PrismaService } from '../prisma/prisma.service';
 import {
@@ -38,6 +39,7 @@ export class BrokerageOperationsService {
     private readonly prisma: PrismaService,
     config: ConfigService<Environment, true>,
     private readonly tbank: TbankClient,
+    private readonly requestContext: RequestContextService,
   ) {
     this.crypto = TbankCrypto.fromBase64(
       config.getOrThrow('TOKEN_ENCRYPTION_KEY'),
@@ -49,6 +51,7 @@ export class BrokerageOperationsService {
     accountId: string,
     query: BrokerageOperationsQueryDto,
   ): Promise<BrokerageOperationsPageDto> {
+    this.requestContext.set({ userId, brokerageAccountId: accountId });
     const range = this.range(query);
     const key = JSON.stringify({ userId, accountId, ...query, ...range });
     const cached = this.pages.get(key);

src/tbank/portfolio.service.spec.ts

@@ -23,10 +23,14 @@ describe('PortfolioService', () => {
     getInstrumentByFigi: jest.fn(),
     getInstrumentByUid: jest.fn(),
   };
+  const requestContext = { set: jest.fn() };
+  const logger = { event: jest.fn() };
   const service = new PortfolioService(
     prisma as never,
     config as never,
     tbank as never,
+    requestContext as never,
+    logger as never,
   );
   const crypto = TbankCrypto.fromBase64(key);
 

src/tbank/portfolio.service.ts

@@ -2,12 +2,13 @@ import {
   BadRequestException,
   ConflictException,
   Injectable,
-  Logger,
   NotFoundException,
   ServiceUnavailableException,
 } from '@nestjs/common';
 import { ConfigService } from '@nestjs/config';
 import { Environment } from '../config/env.validation';
+import { RequestContextService } from '../common/logging/request-context.service';
+import { StructuredLogger } from '../common/logging/structured-logger.service';
 import { PrismaService } from '../prisma/prisma.service';
 import {
   add,
@@ -49,7 +50,6 @@ type CachedMetadata = {
 
 @Injectable()
 export class PortfolioService {
-  private readonly logger = new Logger(PortfolioService.name);
   private readonly crypto: TbankCrypto;
   private readonly snapshots = new Map<string, CachedSnapshot>();
   private readonly metadata = new Map<string, CachedMetadata>();
@@ -58,6 +58,8 @@ export class PortfolioService {
     private readonly prisma: PrismaService,
     config: ConfigService<Environment, true>,
     private readonly tbank: TbankClient,
+    private readonly requestContext: RequestContextService,
+    private readonly logger: StructuredLogger,
   ) {
     this.crypto = TbankCrypto.fromBase64(
       config.getOrThrow('TOKEN_ENCRYPTION_KEY'),
@@ -65,6 +67,7 @@ export class PortfolioService {
   }
 
   async get(userId: string, accountId: string): Promise<PortfolioDto> {
+    this.requestContext.set({ userId, brokerageAccountId: accountId });
     const key = `${userId}:${accountId}`;
     const cached = this.snapshots.get(key);
     if (cached && Date.now() - cached.storedAt <= freshForMs)
@@ -241,16 +244,12 @@ export class PortfolioService {
       try {
         const value = await fetch();
         this.metadata.set(key, { value, storedAt: Date.now() });
-        this.logger.debug({
-          event: 'instrument_metadata_resolved',
-          cacheKey: key,
+        this.logger.event('debug', 'portfolio.instrument-metadata.resolved', {
           found: Boolean(value?.name?.trim() || value?.ticker?.trim()),
         });
         return value;
       } catch (error) {
-        this.logger.warn({
-          event: 'instrument_metadata_failed',
-          cacheKey: key,
+        this.logger.event('warn', 'portfolio.instrument-metadata.failed', {
           code:
             error instanceof Error && 'response' in error
               ? ((error as { response?: { code?: string } }).response?.code ??

src/tbank/tbank.client.spec.ts

@@ -1,4 +1,5 @@
 import { ServiceUnavailableException } from '@nestjs/common';
+import { status } from '@grpc/grpc-js';
 import { TbankClient } from './tbank.client';
 
 describe('TbankClient operations', () => {
@@ -42,4 +43,59 @@ describe('TbankClient operations', () => {
       error,
     );
   });
+
+  it('logs success, retry, and final failure with the RPC context', async () => {
+    jest.useFakeTimers();
+    const logger = { event: jest.fn(), info: jest.fn() };
+    const client = Object.create(TbankClient.prototype) as TbankClient;
+    (client as unknown as { logger: unknown }).logger = logger;
+    (client as unknown as { queue: unknown }).queue = {
+      size: 0,
+      run: (operation: () => unknown) => operation(),
+    };
+    const invoke = (...args: [string, unknown, string, object]) =>
+      (
+        client as unknown as {
+          call: (
+            token: string,
+            service: unknown,
+            method: string,
+            input: object,
+          ) => Promise<unknown>;
+        }
+      ).call(...args);
+    const requestRpc = jest
+      .fn()
+      .mockResolvedValueOnce({ ok: true })
+      .mockRejectedValueOnce({ code: status.UNAVAILABLE })
+      .mockRejectedValueOnce({ code: status.UNAVAILABLE });
+    (client as unknown as { request: jest.Mock }).request = requestRpc;
+
+    await expect(invoke('token', {}, 'getPortfolio', {})).resolves.toEqual({
+      ok: true,
+    });
+    const failed = invoke('token', {}, 'getPortfolio', {});
+    const rejected = expect(failed).rejects.toEqual(
+      expect.any(ServiceUnavailableException),
+    );
+    await jest.advanceTimersByTimeAsync(1000);
+    await rejected;
+
+    expect(logger.event).toHaveBeenCalledWith(
+      'debug',
+      'tbank.rpc.completed',
+      expect.objectContaining({ operation: 'getPortfolio', attempts: 1 }),
+    );
+    expect(logger.event).toHaveBeenCalledWith(
+      'warn',
+      'tbank.rpc.retry',
+      expect.objectContaining({ grpcCode: status.UNAVAILABLE, attempts: 1 }),
+    );
+    expect(logger.event).toHaveBeenCalledWith(
+      'error',
+      'tbank.rpc.failed',
+      expect.objectContaining({ grpcCode: status.UNAVAILABLE, attempts: 2 }),
+    );
+    jest.useRealTimers();
+  });
 });

src/tbank/tbank.client.ts

@@ -1,8 +1,4 @@
-import {
-  Injectable,
-  Logger,
-  ServiceUnavailableException,
-} from '@nestjs/common';
+import { Injectable, ServiceUnavailableException } from '@nestjs/common';
 import { ConfigService } from '@nestjs/config';
 import {
   ChannelCredentials,
@@ -17,6 +13,7 @@ import { loadSync } from '@grpc/proto-loader';
 import { existsSync, readFileSync } from 'node:fs';
 import { join } from 'node:path';
 import { Environment } from '../config/env.validation';
+import { StructuredLogger } from '../common/logging/structured-logger.service';
 
 const requestDeadlineMs = 15_000;
 
@@ -129,13 +126,15 @@ class RateLimiter {
 
 @Injectable()
 export class TbankClient {
-  private readonly logger = new Logger(TbankClient.name);
   private readonly queue: RateLimiter;
   private readonly users: TbankClientService;
   private readonly operations: TbankClientService;
   private readonly instruments: TbankClientService;
 
-  constructor(config: ConfigService<Environment, true>) {
+  constructor(
+    config: ConfigService<Environment, true>,
+    private readonly logger: StructuredLogger,
+  ) {
     const sourceProtoRoot = join(process.cwd(), 'src/tbank/proto/contracts');
     const protoRoot = existsSync(sourceProtoRoot)
       ? sourceProtoRoot
@@ -174,14 +173,7 @@ export class TbankClient {
     this.queue = new RateLimiter(
       config.getOrThrow<number>('TBANK_RATE_LIMIT_PER_SECOND'),
     );
-    this.logger.log({
-      event: 'client_configured',
-      endpoint,
-      rateLimitPerSecond: config.getOrThrow<number>(
-        'TBANK_RATE_LIMIT_PER_SECOND',
-      ),
-      customCa: Boolean(caPath),
-    });
+    this.logger.info('tbank.client.configured');
   }
 
   async validateToken(token: string): Promise<void> {
@@ -242,41 +234,59 @@ export class TbankClient {
     client: TbankClientService,
     method: string,
     request: object,
-    retry = true,
   ): Promise<Response> {
-    if (this.queue.size >= 50)
-      throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' });
-    try {
-      return await this.queue.run(() =>
-        this.request<Response>(token, client, method, request),
-      );
-    } catch (error) {
-      const code = (error as ServiceError).code;
-      const retryable = [
-        status.UNAVAILABLE,
-        status.DEADLINE_EXCEEDED,
-        status.RESOURCE_EXHAUSTED,
-      ].includes(code);
-      this.logger.warn({
-        event: 'tbank_rpc_failed',
-        method,
-        grpcCode: code,
-        retryable,
-        ...(method === 'getInstrumentBy'
-          ? {
-              instrumentIdType: (request as { idType?: string }).idType,
-              instrumentId: (request as { id?: string }).id,
-            }
-          : {}),
+    if (this.queue.size >= 50) {
+      this.logger.event('error', 'tbank.rpc.failed', {
+        operation: method,
+        code: 'TBANK_UNAVAILABLE',
+        attempts: 0,
       });
-      if (retry && retryable) {
-        await new Promise((resolve) => setTimeout(resolve, 1000));
-        return this.call(token, client, method, request, false);
-      }
-      if ([status.UNAUTHENTICATED, status.PERMISSION_DENIED].includes(code))
-        throw new Error('INVALID_TBANK_TOKEN');
       throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' });
     }
+
+    for (let attempts = 1; attempts <= 2; attempts += 1) {
+      const startedAt = performance.now();
+      try {
+        const response = await this.queue.run(() =>
+          this.request<Response>(token, client, method, request),
+        );
+        this.logger.event('debug', 'tbank.rpc.completed', {
+          operation: method,
+          attempts,
+          durationMs: Math.round(performance.now() - startedAt),
+        });
+        return response;
+      } catch (error) {
+        const grpcCode = (error as ServiceError).code;
+        const retryable = [
+          status.UNAVAILABLE,
+          status.DEADLINE_EXCEEDED,
+          status.RESOURCE_EXHAUSTED,
+        ].includes(grpcCode);
+        if (retryable && attempts < 2) {
+          this.logger.event('warn', 'tbank.rpc.retry', {
+            operation: method,
+            grpcCode,
+            attempts,
+            durationMs: Math.round(performance.now() - startedAt),
+          });
+          await new Promise((resolve) => setTimeout(resolve, 1000));
+          continue;
+        }
+        this.logger.event('error', 'tbank.rpc.failed', {
+          operation: method,
+          grpcCode,
+          attempts,
+          durationMs: Math.round(performance.now() - startedAt),
+        });
+        if (
+          [status.UNAUTHENTICATED, status.PERMISSION_DENIED].includes(grpcCode)
+        )
+          throw new Error('INVALID_TBANK_TOKEN');
+        throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' });
+      }
+    }
+    throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' });
   }
 
   private request<Response>(

src/tbank/upcoming-events.service.spec.ts

@@ -22,11 +22,15 @@ describe('UpcomingEventsService', () => {
     getInstrumentByFigi: jest.fn(),
   };
   const moex = { dividends: jest.fn(), bondEvents: jest.fn() };
+  const requestContext = { set: jest.fn() };
+  const logger = { info: jest.fn(), event: jest.fn() };
   const service = new UpcomingEventsService(
     prisma as never,
     config as never,
     tbank as never,
     moex as never,
+    requestContext as never,
+    logger as never,
   );
   const crypto = TbankCrypto.fromBase64(key);
 

src/tbank/upcoming-events.service.ts

@@ -2,11 +2,12 @@ import {
   BadRequestException,
   ConflictException,
   Injectable,
-  Logger,
   NotFoundException,
 } from '@nestjs/common';
 import { ConfigService } from '@nestjs/config';
 import { Environment } from '../config/env.validation';
+import { RequestContextService } from '../common/logging/request-context.service';
+import { StructuredLogger } from '../common/logging/structured-logger.service';
 import { PrismaService } from '../prisma/prisma.service';
 import { decimal, formatDecimal, isZero, multiply } from './decimal';
 import { MoexBondEvent, MoexClient, MoexDividend } from './moex.client';
@@ -26,13 +27,14 @@ type Position = NonNullable<TbankPortfolio['positions']>[number];
 @Injectable()
 export class UpcomingEventsService {
   private readonly crypto: TbankCrypto;
-  private readonly logger = new Logger(UpcomingEventsService.name);
 
   constructor(
     private readonly prisma: PrismaService,
     config: ConfigService<Environment, true>,
     private readonly tbank: TbankClient,
     private readonly moex: MoexClient,
+    private readonly requestContext: RequestContextService,
+    private readonly logger: StructuredLogger,
   ) {
     this.crypto = TbankCrypto.fromBase64(
       config.getOrThrow('TOKEN_ENCRYPTION_KEY'),
@@ -40,6 +42,7 @@ export class UpcomingEventsService {
   }
 
   async get(userId: string, accountId: string): Promise<UpcomingEventsDto> {
+    this.requestContext.set({ userId, brokerageAccountId: accountId });
     try {
       const connection = await this.prisma.tbankConnection.findUnique({
         where: { userId },
@@ -67,13 +70,8 @@ export class UpcomingEventsService {
         .filter(
           (event) => event.date >= window.from && event.date <= window.to,
         );
-      this.logger.log({
-        event: 'upcoming_events_calculated',
-        accountId,
-        from: window.from,
-        to: window.to,
-        positionCount: (portfolio.positions ?? []).length,
-        eventCount: projected.length,
+      this.logger.info('upcoming-events.calculated', {
+        count: projected.length,
       });
       return {
         accountId,
@@ -98,13 +96,8 @@ export class UpcomingEventsService {
   ): Promise<UpcomingEventDto[]> {
     const ticker = position.ticker?.trim();
     const instrument = ticker
-      ? await this.instrument(token, position).catch((error: unknown) => {
-          this.logger.warn({
-            event: 'upcoming_event_metadata_unavailable',
-            figi: position.figi?.trim() || null,
-            ticker,
-            error: error instanceof Error ? error.message : 'UNKNOWN',
-          });
+      ? await this.instrument(token, position).catch(() => {
+          this.logger.event('warn', 'upcoming-events.metadata-unavailable');
           return null;
         })
       : await this.instrument(token, position);
@@ -117,30 +110,16 @@ export class UpcomingEventsService {
       displayName: instrument?.name?.trim() || resolvedTicker,
     };
     const quantity = decimal(position.quantity ?? {});
-    this.logger.debug({
-      event: 'upcoming_event_position_resolved',
-      figi: metadata.figi,
-      portfolioTicker: ticker || null,
-      resolvedTicker,
-      displayName: metadata.displayName,
-      instrumentType: position.instrumentType?.toLowerCase() || null,
-    });
     if (position.instrumentType?.toLowerCase() === 'share') {
       const dividends = await this.moex.dividends(resolvedTicker);
-      this.logger.debug({
-        event: 'upcoming_event_source_result',
-        ticker: resolvedTicker,
-        source: 'dividends',
-        eventCount: dividends.length,
+      this.logger.event('debug', 'upcoming-events.source-result', {
+        count: dividends.length,
       });
       return dividends.map((event) => this.dividend(metadata, quantity, event));
     }
     const events = await this.moex.bondEvents(resolvedTicker);
-    this.logger.debug({
-      event: 'upcoming_event_source_result',
-      ticker: resolvedTicker,
-      source: 'bondization',
-      eventCount: events.length,
+    this.logger.event('debug', 'upcoming-events.source-result', {
+      count: events.length,
     });
     return events.map((event) => this.bond(metadata, quantity, event));
   }