Logging configuration for nestjs-pino

logging.ts

import { Request, Response } from 'express';
import jwt from 'jsonwebtoken';
import { isString } from 'lodash';
import { Params } from 'nestjs-pino/params';
import { Store, storage } from 'nestjs-pino/storage';
import pino, { LoggerOptions, TransportTargetOptions } from 'pino';

import { isRunningLocally, isTestEnvironment } from '@vori/constants/project';

import { maybeInjectTracingData } from '@vori/loggers/tracing';
import { toBool } from '@vori/nest/libs/utils';
import { maskPhoneNumber } from '@vori/otel/utils';
import { DEFAULT_RESOURCE_ATTRIBUTES, getVersion } from '@vori/tracing';

const customAttributeKeys = {
  req: 'request',
  res: 'response',
  err: 'error',
};

const serializers = {
  res(res) {
    // Response headers are noise we don't need.
    delete res.headers;
    return res;
  },
  // Ensure we always log the Axios error response.
  // Adapted from https://github.com/axios/axios/issues/4836#issuecomment-1663818844.
  err: pino.stdSerializers.wrapErrorSerializer((error) => {
    if (error.name === 'AxiosError') {
      const toJSON = error.toJSON.bind(error);
      error.toJSON = () => ({
        ...toJSON(),
        response: {
          data: error.response?.data,
          headers: { ...error.response?.headers },
        },
      });
    }
    return error;
  }),
};

const transports: TransportTargetOptions[] = [];

if (!isTestEnvironment) {
  // NOTE: We don't use Otel in tests, and we don't want this keeping handles open.
  transports.push({
    target: 'pino-opentelemetry-transport',
    options: {
      serviceVersion: getVersion(),
      resourceAttributes: DEFAULT_RESOURCE_ATTRIBUTES,
    },
    level: 'debug',
  });
}

if (isRunningLocally) {
  transports.push({
    target: 'pino-pretty',
    options: {
      colorize: !toBool(process.env.NO_COLOR),
      // NOTE: This should only be enabled for tests. See https://github.com/pinojs/pino-pretty?tab=readme-ov-file#usage-with-jest.
      sync: toBool(process.env.ENABLE_SYNCHRONOUS_LOGGING),
    },
    level: 'debug',
  });
} else {
  // Log to STDOUT. See https://stackoverflow.com/a/77961456/592820.
  transports.push({
    level: 'trace',
    target: 'pino/file',
    options: {
      destination: 1,
    },
  });
}

export const rootPinoLogger = pino(<LoggerOptions>{
  formatters: {
    log: maybeInjectTracingData,
  },
  transport: { targets: transports },
  redact: {
    paths: [
      `${customAttributeKeys.req}.headers.authorization`,

      // We should not log the tokens passed to /v1/lane-provisioning-token.
      `${customAttributeKeys.req}.body.token`,
      `request_body.token`,

      // Do not log private keys from Axios errors (esp. for Blackhawk)
      'err.config.httpsAgent',

      // Surge webhook PII
      'request_body.data.conversation.contact.email',
      'request_body.data.conversation.contact.first_name',
      'request_body.data.conversation.contact.last_name',
      'request_body.data.conversation.contact.phone_number',
    ],
    censor: (value: unknown, path: string[]) => {
      if (path.at(-1) === 'phone_number' && isString(value)) {
        return maskPhoneNumber(value);
      }

      return '[Redacted]';
    },
  },
  serializers,
});

function getJwtProps(req) {
  const AUTH_HEADER_REGEX = new RegExp(/^bearer\s+(?<token>.*)$/i);
  const groups = AUTH_HEADER_REGEX.exec(req.headers.authorization)?.groups;

  if (groups) {
    const { token } = groups;
    const decoded = jwt.decode(token, { complete: true });

    if (!decoded) {
      return undefined;
    }

    const { header, payload } = decoded;
    if (isString(payload)) {
      return {
        kid: header.kid,
        payload: '[Redacted]',
      };
    }

    const exp = payload.exp;

    return {
      aud: payload.aud,
      email: payload.email,
      exp: exp,
      iss: payload.iss,
      kid: header.kid,
      name: payload.name,
      sub: payload.sub,
      user_id: payload.user_id,
      is_expired: !exp || Date.now() >= exp * 1000,
    };
  }

  return undefined;
}

function maybeGetClientIp(req: Request): string | undefined {
  const header = req.header('x-forwarded-for');

  if (!header) {
    return undefined;
  }

  return header.split(',')[0];
}

function shouldLogBody(request: Request) {
  const contentType = request.headers['content-type'];
  return (
    toBool(process.env.LOG_REQUEST_BODY) &&
    contentType &&
    ['application/json', 'application/x-www-form-urlencoded'].includes(
      contentType
    )
  );
}

export function generatePinoParams({
  serviceName,
}: { serviceName?: string } = {}): Params {
  return {
    assignResponse: true,
    pinoHttp: {
      logger: rootPinoLogger,
      level: isRunningLocally ? 'debug' : 'info',
      serializers,
      customLogLevel: function (req: Request, res: Response, error?: Error) {
        if (res.statusCode >= 500 || error) {
          return 'error';
        } else if (res.statusCode >= 400 && res.statusCode < 500) {
          return 'warn';
        }

        if (!res.writableEnded) {
          // Request was probably aborted by gateway/load balancer because processing took too long.
          return 'warn';
        }

        return 'info';
      },
      autoLogging: {
        ignore: (req: Request) => {
          return req.url === '/favicon.ico';
        },
      },
      customAttributeKeys,
      customProps: (req: Request, res: Response) => {
        let props: Record<string, unknown> = {
          // NOTE: Log these details so we can debug incorrect HTTP 401 errors
          jwt: res.statusCode === 401 ? getJwtProps(req) : undefined,
          auth_info: res.statusCode === 401 ? req.authInfo : undefined,
          service: {
            name: serviceName?.toLowerCase(),
          },
          http: {
            client_ip: maybeGetClientIp(req),
          },
        };

        // This method is called twice per request. Some attributes should only
        // apply to the canonical log line. See https://github.com/pinojs/pino-http/issues/216.
        if (res.writableEnded) {
          props = {
            ...props,
            is_canonical: true,
            route: {
              // NOTE: We ideally want this on all logs, but it's set to "/*" on non-canonical log lines.
              path: req.route?.path,
            },
          };

          // NOTE: We only want the body on the canonical log line to avoid exploding the logs
          if (shouldLogBody(req)) {
            let body = undefined;
            if (shouldLogBody(req)) {
              body = req.body;
            }

            props = {
              ...props,
              request_body: body,
            };
          }
        }

        return props;
      },
      customSuccessMessage: (
        req: Request,
        res: Response,
        responseTime: number
      ) => {
        return `[CANONICAL-${serviceName?.toUpperCase()}-REQUEST-LOG] Request ${
          res.writableEnded ? 'completed in' : 'aborted after'
        } ${responseTime}ms`;
      },
      customErrorMessage: (req: Request, res: Response) => {
        return `[CANONICAL-${serviceName?.toUpperCase()}-REQUEST-LOG] Request failed`;
      },
    },
  };
}

/**
 * Method decorator to allow using the nest-pino assign()
 * method outside of a request.
 *
 * Adapted from https://github.com/iamolegga/nestjs-pino/issues/803#issuecomment-1688365477.
 */
export function WithLoggerContext() {
  return function (
    target,
    key: string | symbol,
    descriptor: PropertyDescriptor
  ) {
    const methodFunc = descriptor.value;
    if (!methodFunc) {
      return descriptor;
    }

    if (methodFunc.constructor.name === 'AsyncFunction') {
      descriptor.value = async function (...args) {
        return storage.run(new Store(rootPinoLogger.child({})), async () =>
          methodFunc.apply(this, args)
        );
      };
    } else {
      descriptor.value = function (...args) {
        return storage.run(new Store(rootPinoLogger.child({})), () =>
          methodFunc.apply(this, args)
        );
      };
    }

    return descriptor;
  };
}

  
// NOTE: This is ultimately used by importing `LoggerModule.forRoot(generatePinoParams({ serviceName }))` on the `AppModule`.