Pino (Logging)

main.ts

// bufferLogs: true is a feature that temporarily stores (buffers) 
// all log messages that occur during the application's bootstrap process 
// until the logger is fully configured. Here's why this is important
// prevent logging loss
const app = await NestFactory.create(AppModule, { bufferLogs: true });
// Uses dependency injection to get the logger instance (app.get(Logger))
app.useLogger(app.get(Logger));

app.module.ts

@Module({
  imports: [
   // Declare logger module in global level and customize the setting
    LoggerModule.forRoot({
      pinoHttp: pinoOptionConfig(),
    })
  ],
  providers: [
    {
      provide: APP_FILTER,
      useClass: HttpExceptionFilter,
    },
  ],
})

pino.config.ts

import { Options } from 'pino-http';
import pino from 'pino';
import * as apm from 'elastic-apm-node/start';
const LOG_FILE_BASE_PATH = process.env.LOG_FILE_BASE_PATH ?? '/tmp';
const LOG_FILE_ROTATE_SIZE = process.env.LOG_FILE_ROTATE_SIZE ?? '50M';
const LOG_FILE_MAX_FILE_HISTORY = process.env.LOG_FILE_MAX_FILE_HISTORY ?? 5;

type TransportOptions =
  | pino.TransportSingleOptions<Record<string, any>>
  | pino.TransportMultiOptions<Record<string, any>>
  | pino.TransportPipelineOptions<Record<string, any>>;

const targetOptions = {
  translateTime: 'SYS:yyyy-mm-dd HH:MM:ss.l o',
  ignore: 'res,context,filename',
  singleLine: true,
};

export function pinoOptionConfig(): Options {
  const logLevel = process.env.BOT_BUILDER_BACKEND_LOG_LEVEL || 'info';
  return {
   // min level of log
   // Only logs at this level 
   // or higher will be output (e.g., if set to 'info', debug logs won't show)
    level: logLevel,
   // append the additional field
    mixin: (mergeObject, level) => {
      return { 'level-label': pino.levels.labels[level].toUpperCase(), ...injectApmTraceId() };
    },
    // time of each log
    timestamp: pino.stdTimeFunctions.isoTime,
    // autom log http res and req
    autoLogging: true,
    quietReqLogger: false,
    // the output setting
    transport: configTransport(logLevel),
    // format specific log, such as request
    serializers: {
      req: formatRequestLog,
    },
  };
}

const injectApmTraceId = () => {
  const apmTransaction = {};
  if (apm?.isStarted()) {
    const apmTx = apm.currentTransaction;
    if (apmTx) {
      const apmCurrentTransaction = {};
      apmCurrentTransaction['trace.id'] = apmTx.ids['trace.id'];
      apmCurrentTransaction['transaction.id'] = apmTx.ids['transaction.id'];
      const span = apm.currentSpan;
      if (span) {
        apmCurrentTransaction['span.id'] = span.ids['span.id'];
      }
      apmTransaction['apmTransaction'] = apmCurrentTransaction;
    }
  }
  return apmTransaction;
};

const formatRequestLog = (req: pino.SerializedRequest) => {
  const requestLog: { api: string; gravitee: Record<string, string> | null } = {
    api: `[${req.id}] [${req.method}] [${req.url}]`,
    gravitee: null,
  };
  if (req.headers['x-gravitee-request-id']) {
    requestLog.gravitee = {
      'x-gravitee-request-id': req.headers['x-gravitee-request-id'],
      'x-gravitee-transaction-id': req.headers['x-gravitee-transaction-id'],
    };
  }
  return requestLog;
};

const configTransport = (logLevel: string): TransportOptions => {
  return {
    // console log output setting
    targets: [
      {
        target: 'pino-pretty',
        level: logLevel,
        options: {
          ...targetOptions,
        },
      },
      // file log output setting
      {
        target: require.resolve('./pino-transport-file-rotating'),
        level: logLevel,
        options: {
          size: LOG_FILE_ROTATE_SIZE,
          maxFiles: Number(LOG_FILE_MAX_FILE_HISTORY),
          path: LOG_FILE_BASE_PATH,
        },
      },
    ],
  };
};