Use JSON for logging (safe-global#310)

This PR is heavily inspired by
5afe/safe-gelato-relay-service#72

- Uses JSON as the default logging format – `winston.format.json()` is
now the main formatter
- The `ILoggingService` interface changed to accommodate the new format
– a `message` can now be an unknown payload format or a `string` –
regardless of the type, this value will be logged under `{ message:
<value> }`
- All the logging-related code is found under `src/logging` which makes
it independent from the other service layers. The idea is to maintain
the logging utilities as a shared service that can be injected on demand
in other parts of the service.
- The logging mechanism also adds `nestjs-cls` as a dependency to store
request-wide data (like request ids).
- Some redundant error messages were removed (`http-error.factory.ts`
and `transaction-preview.mapper.ts` for example) since they would be
logged twice with this new setup.

The base format of the logs is as follows:

```javascript
{
  message: <string | object>, // string value or json payload
  request_id: <string>, // id tied to the request
  timestamp: <string>, // ISO 8601 Date string
}
```

The `message` value when logging route requests is as follows:

```javascript
{
  ...
  message: {
      client_ip: <optional string>, // retrieved from the header X-Real-IP. null if not available
      method: <string>, // GET, POST, etc..
      response_time_ms: <number>, // response time in milliseconds
      route: <optional string>, // route which handled the request. Null if no route handled this request (eg.: 404 requests)
      path: <string>, // path of the resource requested
      status_code: <number>, // resulting status code of the request
      detail: <optional string>, // optional message regarding the result of the request
  }
}
```

package.json

@@ -54,6 +54,7 @@
     "ajv": "^8.11.0",
     "axios": "^0.27.2",
     "lodash": "^4.17.21",
+    "nestjs-cls": "^3.3.1",
     "redis": "^4.2.0",
     "reflect-metadata": "^0.1.13",
     "rimraf": "^3.0.2",

src/app.module.ts

@@ -4,10 +4,12 @@ import {
   NestModule,
   RequestMethod,
 } from '@nestjs/common';
+import { APP_INTERCEPTOR } from '@nestjs/core';
+import { ClsMiddleware, ClsModule } from 'nestjs-cls';
+import { v4 as uuidv4 } from 'uuid';
 
 import { ChainsModule } from './routes/chains/chains.module';
 import { BalancesModule } from './routes/balances/balances.module';
-import { LoggerMiddleware } from './middleware/logger.middleware';
 import { NetworkModule } from './datasources/network/network.module';
 import { ConfigurationModule } from './config/configuration.module';
 import { CacheModule } from './datasources/cache/cache.module';
@@ -28,6 +30,9 @@ import { EstimationsModule } from './routes/estimations/estimations.module';
 import { MessagesModule } from './routes/messages/messages.module';
 import { ValidationModule } from './validation/validation.module';
 import { FlushModule } from './routes/flush/flush.module';
+import { RequestScopedLoggingModule } from './logging/logging.module';
+import { RouteLoggerInterceptor } from './routes/common/interceptors/route-logger.interceptor';
+import { NotFoundLoggerMiddleware } from './middleware/not-found-logger.middleware';
 
 @Module({
   imports: [
@@ -51,16 +56,33 @@ import { FlushModule } from './routes/flush/flush.module';
     TransactionsModule,
     // common
     CacheModule,
+    // Module for storing and reading from the async local storage
+    ClsModule.forRoot({
+      global: true,
+      middleware: {
+        generateId: true,
+        idGenerator: () => uuidv4(),
+      },
+    }),
     ConfigurationModule,
     DomainModule,
     NetworkModule,
+    RequestScopedLoggingModule,
     ValidationModule,
   ],
+  providers: [
+    {
+      provide: APP_INTERCEPTOR,
+      useClass: RouteLoggerInterceptor,
+    },
+  ],
 })
 export class AppModule implements NestModule {
   configure(consumer: MiddlewareConsumer) {
     consumer
-      .apply(LoggerMiddleware)
+      // The ClsMiddleware needs to be applied before the LoggerMiddleware
+      // in order to generate the request ids that will be logged afterward
+      .apply(ClsMiddleware, NotFoundLoggerMiddleware)
       .forRoutes({ path: '*', method: RequestMethod.ALL });
   }
 }

src/app.provider.ts

@@ -3,21 +3,6 @@ import { DataSourceErrorFilter } from './routes/common/filters/data-source-error
 import { DocumentBuilder, SwaggerModule } from '@nestjs/swagger';
 import { NestFactory } from '@nestjs/core';
 import { TestingModule } from '@nestjs/testing/testing-module';
-import * as winston from 'winston';
-import { format } from 'winston';
-
-function configureLogger() {
-  winston.add(
-    new winston.transports.Console({
-      level: 'debug',
-      format: format.combine(
-        format.colorize({ all: true }),
-        format.splat(),
-        format.simple(),
-      ),
-    }),
-  );
-}
 
 function configureVersioning(app: INestApplication) {
   app.enableVersioning({
@@ -44,7 +29,6 @@ function configureSwagger(app: INestApplication) {
 }
 
 const DEFAULT_CONFIGURATION: ((app: INestApplication) => void)[] = [
-  configureLogger,
   configureVersioning,
   configureShutdownHooks,
   configureFilters,

src/datasources/cache/cache.first.data.source.spec.ts

@@ -1,11 +1,19 @@
 import { faker } from '@faker-js/faker';
+import { ILoggingService } from '../../logging/logging.interface';
 import { NetworkResponseError } from '../network/entities/network.error.entity';
 import { mockNetworkService } from '../network/__tests__/test.network.module';
 import { CacheFirstDataSource } from './cache.first.data.source';
 import { ICacheService } from './cache.service.interface';
 import { CacheDir } from './entities/cache-dir.entity';
 import { FakeCacheService } from './__tests__/fake.cache.service';
 
+const mockLoggingService = {
+  info: jest.fn(),
+  debug: jest.fn(),
+  error: jest.fn(),
+  warn: jest.fn(),
+} as unknown as ILoggingService;
+
 describe('CacheFirstDataSource', () => {
   let cacheFirstDataSource: CacheFirstDataSource;
   let fakeCacheService: FakeCacheService;
@@ -16,6 +24,7 @@ describe('CacheFirstDataSource', () => {
     cacheFirstDataSource = new CacheFirstDataSource(
       fakeCacheService,
       mockNetworkService,
+      mockLoggingService,
     );
   });
 
@@ -111,6 +120,7 @@ describe('CacheFirstDataSource', () => {
     cacheFirstDataSource = new CacheFirstDataSource(
       mockCache,
       mockNetworkService,
+      mockLoggingService,
     );
 
     const targetUrl = faker.internet.url();

src/datasources/cache/cache.first.data.source.ts

@@ -5,10 +5,13 @@ import {
   NetworkService,
 } from '../network/network.service.interface';
 import { Inject, Injectable } from '@nestjs/common';
-import * as winston from 'winston';
 import { CacheDir } from './entities/cache-dir.entity';
 import { NetworkResponseError } from '../network/entities/network.error.entity';
 import { get } from 'lodash';
+import {
+  LoggingService,
+  ILoggingService,
+} from '../../logging/logging.interface';
 
 /**
  * A data source which tries to retrieve values from cache using
@@ -26,6 +29,7 @@ export class CacheFirstDataSource {
   constructor(
     @Inject(CacheService) private readonly cacheService: ICacheService,
     @Inject(NetworkService) private readonly networkService: INetworkService,
+    @Inject(LoggingService) private readonly loggingService: ILoggingService,
   ) {}
 
   /**
@@ -47,15 +51,23 @@ export class CacheFirstDataSource {
   ): Promise<T> {
     const cached = await this.cacheService.get(cacheDir);
     if (cached != null) {
-      winston.debug(`[Cache] Cache hit: [${cacheDir.key}, ${cacheDir.field}]`);
+      this.loggingService.debug({
+        type: 'cache_hit',
+        key: cacheDir.key,
+        field: cacheDir.field,
+      });
       const cachedData = JSON.parse(cached);
       if (get(cachedData, 'status') === 404) {
         throw new NetworkResponseError(cachedData.status, cachedData.data);
       }
       return cachedData;
     }
     try {
-      winston.debug(`[Cache] Cache miss: [${cacheDir.key}, ${cacheDir.field}]`);
+      this.loggingService.debug({
+        type: 'cache_miss',
+        key: cacheDir.key,
+        field: cacheDir.field,
+      });
       const { data } = await this.networkService.get(url, params);
       const rawJson = JSON.stringify(data);
       await this.cacheService.set(cacheDir, rawJson, expireTimeSeconds);

src/datasources/cache/cache.module.ts

@@ -3,19 +3,25 @@ import { CacheService } from './cache.service.interface';
 import { RedisCacheService } from './redis.cache.service';
 import { createClient } from 'redis';
 import { IConfigurationService } from '../../config/configuration.service.interface';
-import * as winston from 'winston';
+import {
+  ILoggingService,
+  LoggingService,
+} from '../../logging/logging.interface';
 
 export type RedisClientType = ReturnType<typeof createClient>;
 
 async function redisClientFactory(
   configurationService: IConfigurationService,
+  loggingService: ILoggingService,
 ): Promise<RedisClientType> {
   const redisHost = configurationService.getOrThrow<string>('redis.host');
   const redisPort = configurationService.getOrThrow<string>('redis.port');
   const client: RedisClientType = createClient({
     url: `redis://${redisHost}:${redisPort}`,
   });
-  client.on('error', (err) => winston.error('Redis Client Error', err));
+  client.on('error', (err) =>
+    loggingService.error(`Redis client error: ${err}`),
+  );
   client.connect();
   return client;
 }
@@ -26,7 +32,7 @@ async function redisClientFactory(
     {
       provide: 'RedisClient',
       useFactory: redisClientFactory,
-      inject: [IConfigurationService],
+      inject: [IConfigurationService, LoggingService],
     },
     { provide: CacheService, useClass: RedisCacheService },
   ],

src/datasources/cache/redis.cache.service.spec.ts

@@ -1,5 +1,6 @@
 import { faker } from '@faker-js/faker';
 import { FakeConfigurationService } from '../../config/__tests__/fake.configuration.service';
+import { ILoggingService } from '../../logging/logging.interface';
 import { RedisClientType } from './cache.module';
 import { CacheDir } from './entities/cache-dir.entity';
 import { RedisCacheService } from './redis.cache.service';
@@ -16,6 +17,13 @@ const redisClientType = {
 } as unknown as RedisClientType;
 const redisClientTypeMock = jest.mocked(redisClientType);
 
+const mockLoggingService = {
+  info: jest.fn(),
+  debug: jest.fn(),
+  error: jest.fn(),
+  warn: jest.fn(),
+} as unknown as ILoggingService;
+
 describe('RedisCacheService', () => {
   let redisCacheService: RedisCacheService;
   const configurationService = new FakeConfigurationService();
@@ -33,6 +41,7 @@ describe('RedisCacheService', () => {
     redisCacheService = new RedisCacheService(
       redisClientTypeMock,
       configurationService,
+      mockLoggingService,
     );
   });
 

src/datasources/cache/redis.cache.service.ts

@@ -1,6 +1,9 @@
 import { Inject, Injectable, OnModuleDestroy } from '@nestjs/common';
-import * as winston from 'winston';
 import { IConfigurationService } from '../../config/configuration.service.interface';
+import {
+  ILoggingService,
+  LoggingService,
+} from '../../logging/logging.interface';
 import { RedisClientType } from './cache.module';
 import { ICacheService } from './cache.service.interface';
 import { CacheDir } from './entities/cache-dir.entity';
@@ -14,6 +17,7 @@ export class RedisCacheService implements ICacheService, OnModuleDestroy {
     @Inject('RedisClient') private readonly client: RedisClientType,
     @Inject(IConfigurationService)
     private readonly configuration: IConfigurationService,
+    @Inject(LoggingService) private readonly loggingService: ILoggingService,
   ) {
     this.defaultExpirationTimeInSeconds = this.configuration.getOrThrow<number>(
       'expirationTimeInSeconds.default',
@@ -58,22 +62,22 @@ export class RedisCacheService implements ICacheService, OnModuleDestroy {
    * instance is not responding it invokes {@link forceQuit}.
    */
   async onModuleDestroy(): Promise<void> {
-    winston.verbose('Closing Redis connection');
+    this.loggingService.info('Closing Redis connection');
     const forceQuitTimeout = setTimeout(
       this.forceQuit.bind(this),
       this.quitTimeoutInSeconds * 1000,
     );
     await this.client.quit();
     clearTimeout(forceQuitTimeout);
-    winston.verbose('Redis connection closed');
+    this.loggingService.info('Redis connection closed');
   }
 
   /**
    * Forces the closing of the Redis connection associated with this service.
    */
   private async forceQuit() {
-    winston.verbose('Forcing Redis connection close');
+    this.loggingService.warn('Forcing Redis connection close');
     await this.client.disconnect();
-    winston.verbose('Redis connection closed');
+    this.loggingService.warn('Redis connection closed');
   }
 }

src/datasources/errors/http-error-factory.ts

@@ -1,10 +1,9 @@
 import { HttpStatus, Injectable } from '@nestjs/common';
+import { DataSourceError } from '../../domain/errors/data-source.error';
 import {
   NetworkError,
   NetworkResponseError,
 } from '../network/entities/network.error.entity';
-import { DataSourceError } from '../../domain/errors/data-source.error';
-import * as winston from 'winston';
 
 /**
  * Maps a {@link NetworkError} or {@link Error} into a {@link DataSourceError}
@@ -17,23 +16,17 @@ import * as winston from 'winston';
  */
 @Injectable()
 export class HttpErrorFactory {
-  private mapError(error: NetworkError | Error): DataSourceError {
-    if (isNetworkResponseError(error)) {
-      const errorMessage: string = error.data?.message ?? 'An error occurred';
-      return new DataSourceError(errorMessage, error.status);
+  from(source: NetworkError | Error): DataSourceError {
+    if (isNetworkResponseError(source)) {
+      const errorMessage: string = source.data?.message ?? 'An error occurred';
+      return new DataSourceError(errorMessage, source.status);
     } else {
       return new DataSourceError(
         'Service unavailable',
         HttpStatus.SERVICE_UNAVAILABLE,
       );
     }
   }
-
-  from(source: NetworkError | Error): DataSourceError {
-    const error = this.mapError(source);
-    winston.error(error);
-    return error;
-  }
 }
 
 function isNetworkResponseError(

src/datasources/transaction-api/transaction-api.manager.ts

@@ -10,7 +10,6 @@ import {
   INetworkService,
   NetworkService,
 } from '../network/network.service.interface';
-import * as winston from 'winston';
 
 @Injectable()
 export class TransactionApiManager implements ITransactionApiManager {
@@ -25,13 +24,9 @@ export class TransactionApiManager implements ITransactionApiManager {
   ) {}
 
   async getTransactionApi(chainId: string): Promise<TransactionApi> {
-    winston.debug(`Getting TransactionApi instance for chain ${chainId}`);
     const transactionApi = this.transactionApiMap[chainId];
     if (transactionApi !== undefined) return transactionApi;
 
-    winston.debug(
-      `Transaction API for chain ${chainId} not available. Fetching from the Config Service`,
-    );
     const chain: Chain = await this.configApi.getChain(chainId);
     this.transactionApiMap[chainId] = new TransactionApi(
       chainId,

src/logging/__tests__/test.logging.module.ts

@@ -0,0 +1,18 @@
+import { Global, Module } from '@nestjs/common';
+import { ILoggingService, LoggingService } from '../logging.interface';
+
+const loggingService: ILoggingService = {
+  info: console.log,
+  error: console.error,
+  warn: console.warn,
+  debug: console.debug,
+};
+
+const mockLoggingService = jest.mocked(loggingService);
+
+@Global()
+@Module({
+  providers: [{ provide: LoggingService, useValue: mockLoggingService }],
+  exports: [LoggingService],
+})
+export class TestLoggingModule {}

src/logging/logging.interface.ts

@@ -0,0 +1,11 @@
+export const LoggingService = Symbol('ILoggingService');
+
+export interface ILoggingService {
+  info(message: string | unknown): void;
+
+  debug(message: string | unknown): void;
+
+  error(message: string | unknown): void;
+
+  warn(message: string | unknown): void;
+}