diff --git a/package-lock.json b/package-lock.json index f7a3015..e8725bd 100644 --- a/package-lock.json +++ b/package-lock.json @@ -33,9 +33,7 @@ "@nestjs/platform-fastify": "^10.0.0", "@nestjs/swagger": "^7.0.0", "class-validator": "0.13.2", - "nestjs-pino": "^4.0.0", - "pino-http": "^9.0.0", - "pino-pretty": "^10.0.0", + "nestjs-cls": "^4.3.0", "prom-client": "^15.0.0" } }, @@ -2871,12 +2869,6 @@ "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.4.tgz", "integrity": "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==" }, - "node_modules/colorette": { - "version": "2.0.20", - "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", - "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", - "peer": true - }, "node_modules/concat-map": { "version": "0.0.1", "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz", @@ -3007,15 +2999,6 @@ "url": "https://github.com/sponsors/ljharb" } }, - "node_modules/dateformat": { - "version": "4.6.3", - "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", - "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", - "peer": true, - "engines": { - "node": "*" - } - }, "node_modules/debug": { "version": "4.3.4", "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz", @@ -3189,15 +3172,6 @@ "integrity": "sha512-MSjYzcWNOA0ewAHpz0MxpYFvwg6yjy1NG3xteoqz644VCo/RPgnr1/GGt+ic3iJTzQ8Eu3TdM14SawnVUmGE6A==", "dev": true }, - "node_modules/end-of-stream": { - "version": "1.4.4", - "resolved": "https://registry.npmjs.org/end-of-stream/-/end-of-stream-1.4.4.tgz", - "integrity": "sha512-+uw1inIHVPQoaVuHzRyXd21icM+cnt4CzD5rW+NC1wjOUSTOs+Te7FOv7AhN7vS9x/oIyhLP5PR1H+phQAHu5Q==", - "peer": true, - "dependencies": { - "once": "^1.4.0" - } - }, "node_modules/error-ex": { "version": "1.3.2", "resolved": "https://registry.npmjs.org/error-ex/-/error-ex-1.3.2.tgz", @@ -3718,12 +3692,6 @@ "integrity": "sha512-fBHHqSTFLVnR61C+gltJuE5GkVQMV0S2nqUO8TJ+5Z3qAKG8vAx4FKai1s5jq/inV1+sREynIWSuQ6HgoSXpDQ==", "peer": true }, - "node_modules/fast-copy": { - "version": "3.0.2", - "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-3.0.2.tgz", - "integrity": "sha512-dl0O9Vhju8IrcLndv2eU4ldt1ftXMqqfgN4H1cpmGV7P6jeB9FwpN9a2c8DPGE1Ys88rNUJVYDHq73CGAGOPfQ==", - "peer": true - }, "node_modules/fast-decode-uri-component": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/fast-decode-uri-component/-/fast-decode-uri-component-1.0.1.tgz", @@ -4080,6 +4048,7 @@ "version": "2.0.5", "resolved": "https://registry.npmjs.org/get-caller-file/-/get-caller-file-2.0.5.tgz", "integrity": "sha512-DyFP3BM/3YHTQOCUL/w0OZHR0lpKeGrxotcHWcqNEdnltqFwXVfhEBQ94eIo34AfQpo0rGki4cyIiftY06h2Fg==", + "dev": true, "engines": { "node": "6.* || 8.* || >= 10.*" } @@ -4337,12 +4306,6 @@ "node": ">= 0.4" } }, - "node_modules/help-me": { - "version": "5.0.0", - "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", - "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==", - "peer": true - }, "node_modules/html-escaper": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/html-escaper/-/html-escaper-2.0.2.tgz", @@ -5422,15 +5385,6 @@ "url": "https://github.com/chalk/supports-color?sponsor=1" } }, - "node_modules/joycon": { - "version": "3.1.1", - "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", - "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", - "peer": true, - "engines": { - "node": ">=10" - } - }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -5704,6 +5658,7 @@ "version": "1.2.8", "resolved": "https://registry.npmjs.org/minimist/-/minimist-1.2.8.tgz", "integrity": "sha512-2yyAR8qBkN3YuheJanUpWC5U3bb5osDywNB8RzDVlDwDHbocAJveqqj1u8+SVD7jkWT4yvsHCpWqqWqAxb0zCA==", + "dev": true, "funding": { "url": "https://github.com/sponsors/ljharb" } @@ -5734,18 +5689,19 @@ "integrity": "sha512-Tj+HTDSJJKaZnfiuw+iaF9skdPpTo2GtEly5JHnWV/hfv2Qj/9RKsGISQtLh2ox3l5EAGw487hnBee0sIJ6v2g==", "dev": true }, - "node_modules/nestjs-pino": { - "version": "4.0.0", - "resolved": "https://registry.npmjs.org/nestjs-pino/-/nestjs-pino-4.0.0.tgz", - "integrity": "sha512-XhCg/R+l3w0BFP6MHyR6lU/BHVEV0tV9z24G0vuA9FD3sv+TQNvnO9uVsF1l/oVspgGfQ9Qulmb2UbsfYlI0+g==", - "hasInstallScript": true, + "node_modules/nestjs-cls": { + "version": "4.3.0", + "resolved": "https://registry.npmjs.org/nestjs-cls/-/nestjs-cls-4.3.0.tgz", + "integrity": "sha512-MVTun6tqCZih8AJXRj8uBuuFyJhQrIA9m9fStiQjbBXUkE3BrlMRvmLzyw8UcneB3xtFFTfwkAh5PYKRulyaOg==", "peer": true, "engines": { - "node": ">= 14" + "node": ">=16" }, "peerDependencies": { - "@nestjs/common": "^8.0.0 || ^9.0.0 || ^10.0.0", - "pino-http": "^6.4.0 || ^7.0.0 || ^8.0.0 || ^9.0.0" + "@nestjs/common": "> 7.0.0 < 11", + "@nestjs/core": "> 7.0.0 < 11", + "reflect-metadata": "*", + "rxjs": ">= 7" } }, "node_modules/node-fetch": { @@ -6075,43 +6031,6 @@ "split2": "^4.0.0" } }, - "node_modules/pino-http": { - "version": "9.0.0", - "resolved": "https://registry.npmjs.org/pino-http/-/pino-http-9.0.0.tgz", - "integrity": "sha512-Q9QDNEz0vQmbJtMFjOVr2c9yL92vHudjmr3s3m6J1hbw3DBGFZJm3TIj9TWyynZ4GEsEA9SOtni4heRUr6lNOg==", - "peer": true, - "dependencies": { - "get-caller-file": "^2.0.5", - "pino": "^8.17.1", - "pino-std-serializers": "^6.2.2", - "process-warning": "^3.0.0" - } - }, - "node_modules/pino-pretty": { - "version": "10.3.1", - "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-10.3.1.tgz", - "integrity": "sha512-az8JbIYeN/1iLj2t0jR9DV48/LQ3RC6hZPpapKPkb84Q+yTidMCpgWxIT3N0flnBDilyBQ1luWNpOeJptjdp/g==", - "peer": true, - "dependencies": { - "colorette": "^2.0.7", - "dateformat": "^4.6.3", - "fast-copy": "^3.0.0", - "fast-safe-stringify": "^2.1.1", - "help-me": "^5.0.0", - "joycon": "^3.1.1", - "minimist": "^1.2.6", - "on-exit-leak-free": "^2.1.0", - "pino-abstract-transport": "^1.0.0", - "pump": "^3.0.0", - "readable-stream": "^4.0.0", - "secure-json-parse": "^2.4.0", - "sonic-boom": "^3.0.0", - "strip-json-comments": "^3.1.1" - }, - "bin": { - "pino-pretty": "bin.js" - } - }, "node_modules/pino-std-serializers": { "version": "6.2.2", "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-6.2.2.tgz", @@ -6316,16 +6235,6 @@ "node": ">= 0.10" } }, - "node_modules/pump": { - "version": "3.0.0", - "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", - "integrity": "sha512-LwZy+p3SFs1Pytd/jYct4wpv49HiYCqd9Rlc5ZVdk0V+8Yzv6jR5Blk3TRmPL1ft69TxP0IMZGJ+WPFU2BFhww==", - "peer": true, - "dependencies": { - "end-of-stream": "^1.1.0", - "once": "^1.3.1" - } - }, "node_modules/punycode": { "version": "2.3.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.3.1.tgz", @@ -6959,6 +6868,7 @@ "version": "3.1.1", "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-3.1.1.tgz", "integrity": "sha512-6fPc+R4ihwqP6N/aIv2f1gMH8lOVtWQHoqC4yK6oSDVVocumAsfCqjkXnqiYMhmMwS/mEHLp7Vehlt3ql6lEig==", + "dev": true, "engines": { "node": ">=8" }, diff --git a/package.json b/package.json index 3f7bc2d..faf44b5 100644 --- a/package.json +++ b/package.json @@ -43,9 +43,7 @@ "@nestjs/platform-fastify": "^10.0.0", "@nestjs/swagger": "^7.0.0", "class-validator": "0.13.2", - "nestjs-pino": "^4.0.0", - "pino-http": "^9.0.0", - "pino-pretty": "^10.0.0", + "nestjs-cls": "^4.3.0", "prom-client": "^15.0.0" }, "jest": { diff --git a/src/index.ts b/src/index.ts index a6757e3..9149311 100644 --- a/src/index.ts +++ b/src/index.ts @@ -5,3 +5,4 @@ export * from './modules/actuator'; export * from './modules/config'; export * from './modules/healthcheck'; export * from './modules/prometheus'; +export * from './modules/logging'; diff --git a/src/modules/graceful-shutdown/fastify-gs-plugin.ts b/src/modules/graceful-shutdown/fastify-gs-plugin.ts index a57041e..1c23849 100644 --- a/src/modules/graceful-shutdown/fastify-gs-plugin.ts +++ b/src/modules/graceful-shutdown/fastify-gs-plugin.ts @@ -1,4 +1,4 @@ -import type { Logger } from '@nestjs/common'; +import type { LoggerService } from '@nestjs/common'; import type { NestFastifyApplication } from '@nestjs/platform-fastify'; import type { FastifyInstance, FastifyRequest } from 'fastify'; import { debounce, type DebouncedFunction } from './debounce'; @@ -8,7 +8,7 @@ import { debounce, type DebouncedFunction } from './debounce'; export async function setupGracefulShutdown( app: NestFastifyApplication, - logger: Logger, + logger: LoggerService, ) { // eslint-disable-next-line @typescript-eslint/require-await async function fastifyGracefulShutdownPlugin(fastify: FastifyInstance) { diff --git a/src/modules/logging/config.ts b/src/modules/logging/config.ts index 2d3be99..9a2af53 100644 --- a/src/modules/logging/config.ts +++ b/src/modules/logging/config.ts @@ -6,19 +6,16 @@ export enum LOG_LEVEL { WARN = 'warn', INFO = 'info', DEBUG = 'debug', - TRACE = 'trace', + VERBOSE = 'verbose', } -export type LoggerModuleConfig = { +export type LoggingModuleConfig = { prettyMode: boolean; level: LOG_LEVEL; - - enableHttpTracing: boolean; - enableHttpRequestContext: boolean; }; export type LoggerModuleOpts = { - config: LoggerModuleConfig; + config: LoggingModuleConfig; dependencies: { meterRegistry?: MeterRegistryType; diff --git a/src/modules/logging/create-pino-http-opts.ts b/src/modules/logging/create-pino-http-opts.ts deleted file mode 100644 index 10a9fc9..0000000 --- a/src/modules/logging/create-pino-http-opts.ts +++ /dev/null @@ -1,53 +0,0 @@ -import type { MeterRegistryType } from '@monkee/small-standards'; -import type { Options } from 'pino-http'; -import type { LoggerModuleConfig } from './config'; -import { PinoMetrics } from './pino-metrics'; - -export const createPinoHttpOpts = ( - config: LoggerModuleConfig, - registry?: MeterRegistryType, -): Options => { - let metrics: PinoMetrics | undefined; - - if (registry !== undefined) { - metrics = new PinoMetrics(registry); - } - - return { - // disable pid and hostname - base: undefined, - level: config.level, - messageKey: 'message', - // https://github.com/pinojs/pino/issues/674 - timestamp: () => `,"timestamp":"${Date.now()}"`, - // // Default numeric levels is not human-readable and not supported by logging tools well - // // https://github.com/grafana/grafana/blob/master/packages/grafana-data/src/types/logs.ts#L9-L27 - formatters: { - level(label) { - return { level: label }; - }, - }, - transport: config.prettyMode - ? { - target: 'pino-pretty', - options: { - colorize: true, - levelFirst: true, - messageKey: 'message', - timestampKey: 'timestamp', - }, - } - : undefined, - autoLogging: config.enableHttpTracing, - quietReqLogger: !config.enableHttpRequestContext, - hooks: { - logMethod(inputArgs, method, level) { - metrics?.incrementLogEvent(level); - return method.apply(this, inputArgs); - }, - }, - customAttributeKeys: { - reqId: 'traceId', - }, - }; -}; diff --git a/src/modules/logging/index.ts b/src/modules/logging/index.ts index 6bc7b29..816cc3f 100644 --- a/src/modules/logging/index.ts +++ b/src/modules/logging/index.ts @@ -1,3 +1,3 @@ -export * from './toplevel-hack/toplevel-logger'; -export * from './create-pino-http-opts'; export * from './config'; +export * from './nestjs-logger-fork/structured-logger'; +export * from './logging.module'; diff --git a/src/modules/logging/logging.module-def.ts b/src/modules/logging/logging.module-def.ts new file mode 100644 index 0000000..c258288 --- /dev/null +++ b/src/modules/logging/logging.module-def.ts @@ -0,0 +1,12 @@ +import { ConfigurableModuleBuilder } from '@nestjs/common'; +import type { LoggerModuleOpts } from './config'; + +export const { + ConfigurableModuleClass, + MODULE_OPTIONS_TOKEN, + OPTIONS_TYPE, + ASYNC_OPTIONS_TYPE, +} = new ConfigurableModuleBuilder() + .setExtras({ isGlobal: true }) + .setClassMethodName('forRoot') + .build(); diff --git a/src/modules/logging/logging.module.ts b/src/modules/logging/logging.module.ts new file mode 100644 index 0000000..f57a4be --- /dev/null +++ b/src/modules/logging/logging.module.ts @@ -0,0 +1,10 @@ +import { Global, Module } from '@nestjs/common'; +import { ConfigurableModuleClass } from './logging.module-def'; +import { StructuredLogger } from './nestjs-logger-fork/structured-logger'; + +@Module({ + providers: [StructuredLogger], + exports: [StructuredLogger], +}) +@Global() +export class LoggingModule extends ConfigurableModuleClass {} diff --git a/src/modules/logging/nestjs-logger-fork/cli-colors.util.ts b/src/modules/logging/nestjs-logger-fork/cli-colors.util.ts new file mode 100644 index 0000000..8f5afc2 --- /dev/null +++ b/src/modules/logging/nestjs-logger-fork/cli-colors.util.ts @@ -0,0 +1,18 @@ +type ColorTextFn = (text: string) => string; + +const isColorAllowed = () => process.env.NO_COLOR !== 'true'; +const colorIfAllowed = (colorFn: ColorTextFn) => (text: string) => + isColorAllowed() ? colorFn(text) : text; + +export const clc = { + bold: colorIfAllowed((text: string) => `\x1B[1m${text}\x1B[0m`), + green: colorIfAllowed((text: string) => `\x1B[32m${text}\x1B[39m`), + yellow: colorIfAllowed((text: string) => `\x1B[33m${text}\x1B[39m`), + red: colorIfAllowed((text: string) => `\x1B[31m${text}\x1B[39m`), + magentaBright: colorIfAllowed((text: string) => `\x1B[95m${text}\x1B[39m`), + cyanBright: colorIfAllowed((text: string) => `\x1B[96m${text}\x1B[39m`), +}; + +export const yellow = colorIfAllowed( + (text: string) => `\x1B[38;5;3m${text}\x1B[39m`, +); diff --git a/src/modules/logging/nestjs-logger-fork/structured-logger.ts b/src/modules/logging/nestjs-logger-fork/structured-logger.ts new file mode 100644 index 0000000..a8f320f --- /dev/null +++ b/src/modules/logging/nestjs-logger-fork/structured-logger.ts @@ -0,0 +1,345 @@ +/* eslint-disable @typescript-eslint/strict-boolean-expressions */ +/* eslint-disable @typescript-eslint/no-explicit-any */ +import * as util from 'node:util'; +import type { CounterType } from '@monkee/small-standards'; +import type { LoggerService } from '@nestjs/common'; +import { Inject, Injectable } from '@nestjs/common'; +import { ClsService } from 'nestjs-cls'; +import { LOG_LEVEL, LoggerModuleOpts } from '../config'; +import { MODULE_OPTIONS_TOKEN } from '../logging.module-def'; +import type { StructuredLog } from '../structured-log'; +import { clc, yellow } from './cli-colors.util'; +import { isFunction, isPlainObject, isString, isUndefined } from './utils'; + +const dateTimeFormatter = new Intl.DateTimeFormat(undefined, { + hour: 'numeric', + minute: 'numeric', + second: 'numeric', + hourCycle: 'h23', +}); + +const logLevelsSorted: LOG_LEVEL[] = [ + LOG_LEVEL.VERBOSE, + LOG_LEVEL.DEBUG, + LOG_LEVEL.INFO, + LOG_LEVEL.WARN, + LOG_LEVEL.ERROR, + LOG_LEVEL.FATAL, +]; + +const defaultLevels: LogLevelSettings = { + [LOG_LEVEL.VERBOSE]: false, + [LOG_LEVEL.DEBUG]: false, + [LOG_LEVEL.INFO]: false, + [LOG_LEVEL.WARN]: false, + [LOG_LEVEL.ERROR]: false, + [LOG_LEVEL.FATAL]: false, +}; + +type LogLevelSettings = { + [key in LOG_LEVEL]: boolean; +}; + +const getSettingsByLevel = (level: LOG_LEVEL): LogLevelSettings => { + const enabledIndex = logLevelsSorted.findIndex((l) => l === level); + + return logLevelsSorted.reduce((acc, l, index) => { + acc[l] = index >= enabledIndex; + return acc; + }, defaultLevels); +}; + +@Injectable() +export class StructuredLogger implements LoggerService { + private readonly levelSettings: LogLevelSettings; + private logEventsCounter?: CounterType; + + constructor( + @Inject(MODULE_OPTIONS_TOKEN) + private opts: LoggerModuleOpts, + private readonly cls?: ClsService, + ) { + this.levelSettings = getSettingsByLevel(opts.config.level); + + if (opts.dependencies.meterRegistry !== undefined) { + this.logEventsCounter = opts.dependencies.meterRegistry.createCounter( + 'nest_log_events_total', + 'Total count of log events', + ['level'], + ); + } + } + + /** + * Write a 'log' level log, if the configured level allows for it. + * Prints to `stdout` with newline. + */ + log(message: any, context?: string): void; + log(message: any, ...optionalParams: [...any, string?]): void; + log(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.INFO, message, ...optionalParams); + } + + /** + * Write an 'error' level log, if the configured level allows for it. + * Prints to `stderr` with newline. + */ + error(message: any, stackOrContext?: string): void; + error(message: any, stack?: string, context?: string): void; + error(message: any, ...optionalParams: [...any, string?, string?]): void; + error(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.ERROR, message, ...optionalParams); + } + + /** + * Write a 'warn' level log, if the configured level allows for it. + * Prints to `stdout` with newline. + */ + warn(message: any, context?: string): void; + warn(message: any, ...optionalParams: [...any, string?]): void; + warn(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.WARN, message, ...optionalParams); + } + + /** + * Write a 'debug' level log, if the configured level allows for it. + * Prints to `stdout` with newline. + */ + debug(message: any, context?: string): void; + debug(message: any, ...optionalParams: [...any, string?]): void; + debug(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.DEBUG, message, ...optionalParams); + } + + /** + * Write a 'verbose' level log, if the configured level allows for it. + * Prints to `stdout` with newline. + */ + verbose(message: any, context?: string): void; + verbose(message: any, ...optionalParams: [...any, string?]): void; + verbose(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.VERBOSE, message, ...optionalParams); + } + + /** + * Write a 'fatal' level log, if the configured level allows for it. + * Prints to `stdout` with newline. + */ + fatal(message: any, context?: string): void; + fatal(message: any, ...optionalParams: [...any, string?]): void; + fatal(message: any, ...optionalParams: any[]) { + this.logInternal(LOG_LEVEL.FATAL, message, ...optionalParams); + } + + private logInternal( + level: LOG_LEVEL, + message: any, + ...optionalParams: any[] + ) { + if (!this.levelSettings[level]) { + return; + } + + this.logEventsCounter?.increment(1, { level }); + + if (this.opts.config.prettyMode) { + if (level === LOG_LEVEL.ERROR) { + const { messages, context, stack } = + this.getContextAndStackAndMessagesToPrint([ + message, + ...optionalParams, + ]); + + this.printMessages(messages, context, level, 'stderr'); + this.printStackTrace(stack!); + } else { + const { messages, context } = this.getContextAndMessagesToPrint([ + message, + ...optionalParams, + ]); + + this.printMessages(messages, context, level); + } + } else { + const structured = this.getStructuredLog( + level, + message, + ...optionalParams, + ); + + if (level === LOG_LEVEL.ERROR) { + process.stderr.write(`${JSON.stringify(structured)}\n`); + } else { + process.stdout.write(`${JSON.stringify(structured)}\n`); + } + } + } + + private getStructuredLog( + level: LOG_LEVEL, + message: any, + ...optionalParams: any[] + ): StructuredLog { + const { messages, context } = this.getContextAndMessagesToPrint([ + message, + ...optionalParams, + ]); + + const formattedMessage = messages + .map((m) => { + return util.format(m); + }) + .join(' '); + + return { + level, + message: formattedMessage, + timestamp: Date.now(), + context: context ?? 'unknown', + traceId: this.cls?.getId(), + }; + } + + protected getTimestamp(): string { + return dateTimeFormatter.format(Date.now()); + } + + protected printMessages( + messages: unknown[], + context = '', + logLevel: LOG_LEVEL, + writeStreamType?: 'stdout' | 'stderr', + ) { + messages.forEach((message) => { + const contextMessage = this.formatContext(context); + const formattedLogLevel = logLevel.toUpperCase().padEnd(7, ' '); + const formattedMessage = this.formatMessage( + logLevel, + message, + formattedLogLevel, + contextMessage, + ); + + process[writeStreamType ?? 'stdout'].write(formattedMessage); + }); + } + + protected formatContext(context: string): string { + return context ? yellow(`[${context}] `) : ''; + } + + protected formatMessage( + logLevel: LOG_LEVEL, + message: unknown, + formattedLogLevel: string, + contextMessage: string, + ) { + const output = this.stringifyMessage(message, logLevel); + formattedLogLevel = this.colorize(formattedLogLevel, logLevel); + return `${this.getTimestamp()} ${formattedLogLevel} ${contextMessage}${output}\n`; + } + + protected stringifyMessage(message: unknown, logLevel: LOG_LEVEL): any { + if (isFunction(message)) { + const messageAsStr = Function.prototype.toString.call(message); + const isClass = messageAsStr.startsWith('class '); + if (isClass) { + // If the message is a class, we will display the class name. + return this.stringifyMessage(message.name, logLevel); + } + // If the message is a non-class function, call it and re-resolve its value. + return this.stringifyMessage(message(), logLevel); + } + + return isPlainObject(message) || Array.isArray(message) + ? `${this.colorize('Object:', logLevel)}\n${JSON.stringify( + message, + (key, value) => + typeof value === 'bigint' ? value.toString() : value, + 2, + )}\n` + : this.colorize(message as string, logLevel); + } + + protected colorize(message: string, logLevel: LOG_LEVEL) { + const color = this.getColorByLogLevel(logLevel); + return color(message); + } + + protected printStackTrace(stack: string) { + if (!stack) { + return; + } + process.stderr.write(`${stack}\n`); + } + + private getContextAndMessagesToPrint(args: unknown[]) { + if (args?.length <= 1) { + return { messages: args }; + } + const lastElement = args[args.length - 1]; + const isContext = isString(lastElement); + if (!isContext) { + return { messages: args }; + } + return { + context: lastElement as string, + messages: args.slice(0, args.length - 1), + }; + } + + private getContextAndStackAndMessagesToPrint(args: unknown[]) { + if (args.length === 2) { + return this.isStackFormat(args[1]) + ? { + messages: [args[0]], + stack: args[1] as string, + } + : { + messages: [args[0]], + context: args[1] as string, + }; + } + + const { messages, context } = this.getContextAndMessagesToPrint(args); + if (messages?.length <= 1) { + return { messages, context }; + } + const lastElement = messages[messages.length - 1]; + const isStack = isString(lastElement); + // https://github.com/nestjs/nest/issues/11074#issuecomment-1421680060 + if (!isStack && !isUndefined(lastElement)) { + return { messages, context }; + } + return { + stack: lastElement as string, + messages: messages.slice(0, messages.length - 1), + context, + }; + } + + private isStackFormat(stack: unknown) { + if (!isString(stack) && !isUndefined(stack)) { + return false; + } + + return /^(.)+\n\s+at .+:\d+:\d+/.test(stack!); + } + + private getColorByLogLevel(level: LOG_LEVEL) { + switch (level) { + case LOG_LEVEL.DEBUG: + return clc.magentaBright; + case LOG_LEVEL.WARN: + return clc.yellow; + case LOG_LEVEL.ERROR: + return clc.red; + case LOG_LEVEL.VERBOSE: + return clc.cyanBright; + case LOG_LEVEL.FATAL: + return clc.bold; + default: + return clc.green; + } + } +} diff --git a/src/modules/logging/nestjs-logger-fork/utils.ts b/src/modules/logging/nestjs-logger-fork/utils.ts new file mode 100644 index 0000000..2f78d4c --- /dev/null +++ b/src/modules/logging/nestjs-logger-fork/utils.ts @@ -0,0 +1,33 @@ +/* eslint-disable @typescript-eslint/no-use-before-define */ +export const isUndefined = (obj: unknown): obj is undefined => + typeof obj === 'undefined'; + +export const isObject = (fn: unknown): fn is object => + !isNil(fn) && typeof fn === 'object'; + +export const isPlainObject = (fn: unknown): fn is object => { + if (!isObject(fn)) { + return false; + } + const proto = Object.getPrototypeOf(fn); + if (proto === null) { + return true; + } + const ctor = + Object.prototype.hasOwnProperty.call(proto, 'constructor') && + proto.constructor; + return ( + typeof ctor === 'function' && + ctor instanceof ctor && + Function.prototype.toString.call(ctor) === + Function.prototype.toString.call(Object) + ); +}; + +// eslint-disable-next-line @typescript-eslint/ban-types +export const isFunction = (val: unknown): val is Function => + typeof val === 'function'; +export const isString = (val: unknown): val is string => + typeof val === 'string'; +export const isNil = (val: unknown): val is null | undefined => + isUndefined(val) || val === null; diff --git a/src/modules/logging/pino-metrics.ts b/src/modules/logging/pino-metrics.ts deleted file mode 100644 index f44c336..0000000 --- a/src/modules/logging/pino-metrics.ts +++ /dev/null @@ -1,29 +0,0 @@ -import type { CounterType } from '@monkee/small-standards'; -import { MeterRegistryType } from '@monkee/small-standards'; - -export class PinoMetrics { - private logsEvents: CounterType; - - private static levelMappings: Record = { - 10: 'trace', - 20: 'debug', - 30: 'info', - 40: 'warn', - 50: 'error', - 60: 'fatal', - }; - - constructor(registry: MeterRegistryType) { - this.logsEvents = registry.createCounter( - 'nest_log_events_total', - 'Total count of log events', - ['level'], - ); - } - - incrementLogEvent(level: number) { - const levelName = PinoMetrics.levelMappings[level]; - - this.logsEvents.increment(1, { level: levelName ?? 'unknown' }); - } -} diff --git a/src/modules/logging/structured-log.ts b/src/modules/logging/structured-log.ts new file mode 100644 index 0000000..d379d27 --- /dev/null +++ b/src/modules/logging/structured-log.ts @@ -0,0 +1,8 @@ +export type StructuredLog = { + timestamp: number; + level: string; + message: string; + context: string; + traceId?: string; + [key: string]: unknown; +}; diff --git a/src/modules/logging/toplevel-hack/toplevel-logger.ts b/src/modules/logging/toplevel-hack/toplevel-logger.ts deleted file mode 100644 index 92e90e8..0000000 --- a/src/modules/logging/toplevel-hack/toplevel-logger.ts +++ /dev/null @@ -1,18 +0,0 @@ -import type { LoggerService } from '@nestjs/common'; -import pino from 'pino'; -import type { LoggerModuleConfig } from '../config'; -import { createPinoHttpOpts } from '../create-pino-http-opts'; -import { ToplvlNestLogger } from './toplvl-nest-logger'; -import { ToplvlPinoLogger } from './toplvl-pino-logger'; - -export const createNestLogger = (config: LoggerModuleConfig): LoggerService => { - const pinoInstance = pino({ - ...createPinoHttpOpts(config), - }); - - const pinoAdapter = new ToplvlPinoLogger('context', pinoInstance); - - return new ToplvlNestLogger(pinoAdapter, 'context'); - - // return new Logger(pino, {}); -}; diff --git a/src/modules/logging/toplevel-hack/toplvl-nest-logger.ts b/src/modules/logging/toplevel-hack/toplvl-nest-logger.ts deleted file mode 100644 index 0ad34eb..0000000 --- a/src/modules/logging/toplevel-hack/toplvl-nest-logger.ts +++ /dev/null @@ -1,91 +0,0 @@ -// external lib -/* eslint-disable @typescript-eslint/no-explicit-any */ -import type { LoggerService } from '@nestjs/common'; -import type { Level } from 'pino'; -import { ToplvlPinoLogger } from './toplvl-pino-logger'; - -export class ToplvlNestLogger implements LoggerService { - constructor( - protected readonly logger: ToplvlPinoLogger, - private readonly contextName: string, - ) {} - - verbose(message: any, ...optionalParams: any[]) { - this.call('trace', message, ...optionalParams); - } - - debug(message: any, ...optionalParams: any[]) { - this.call('debug', message, ...optionalParams); - } - - log(message: any, ...optionalParams: any[]) { - this.call('info', message, ...optionalParams); - } - - warn(message: any, ...optionalParams: any[]) { - this.call('warn', message, ...optionalParams); - } - - error(message: any, ...optionalParams: any[]) { - this.call('error', message, ...optionalParams); - } - - private call(level: Level, message: any, ...optionalParams: any[]) { - const objArg: Record = {}; - - // optionalParams contains extra params passed to logger - // context name is the last item - let params: any[] = []; - if (optionalParams.length !== 0) { - objArg[this.contextName] = optionalParams[optionalParams.length - 1]; - params = optionalParams.slice(0, -1); - } - - if (typeof message === 'object') { - if (message instanceof Error) { - objArg.err = message; - } else { - Object.assign(objArg, message); - } - this.logger[level](objArg, ...params); - } else if (this.isWrongExceptionsHandlerContract(level, message, params)) { - objArg.err = new Error(message); - objArg.err.stack = params[0]; - this.logger[level](objArg); - } else { - this.logger[level](objArg, message, ...params); - } - } - - /** - * Unfortunately built-in (not only) `^.*Exception(s?)Handler$` classes call `.error` - * method with not supported contract: - * - * - ExceptionsHandler - * @see https://github.com/nestjs/nest/blob/35baf7a077bb972469097c5fea2f184b7babadfc/packages/core/exceptions/base-exception-filter.ts#L60-L63 - * - * - ExceptionHandler - * @see https://github.com/nestjs/nest/blob/99ee3fd99341bcddfa408d1604050a9571b19bc9/packages/core/errors/exception-handler.ts#L9 - * - * - WsExceptionsHandler - * @see https://github.com/nestjs/nest/blob/9d0551ff25c5085703bcebfa7ff3b6952869e794/packages/websockets/exceptions/base-ws-exception-filter.ts#L47-L50 - * - * - RpcExceptionsHandler @see https://github.com/nestjs/nest/blob/9d0551ff25c5085703bcebfa7ff3b6952869e794/packages/microservices/exceptions/base-rpc-exception-filter.ts#L26-L30 - * - * - all of them - * @see https://github.com/search?l=TypeScript&q=org%3Anestjs+logger+error+stack&type=Code - */ - private isWrongExceptionsHandlerContract( - level: Level, - message: any, - params: any[], - ): params is [string] { - return ( - level === 'error' && - typeof message === 'string' && - params.length === 1 && - typeof params[0] === 'string' && - /\n\s*at /.test(params[0]) - ); - } -} diff --git a/src/modules/logging/toplevel-hack/toplvl-pino-logger.ts b/src/modules/logging/toplevel-hack/toplvl-pino-logger.ts deleted file mode 100644 index 41ddee1..0000000 --- a/src/modules/logging/toplevel-hack/toplvl-pino-logger.ts +++ /dev/null @@ -1,96 +0,0 @@ -// external lib -/* eslint-disable @typescript-eslint/no-explicit-any */ -/* eslint-disable @typescript-eslint/strict-boolean-expressions */ -import pino from 'pino'; - -type PinoMethods = Pick< - pino.Logger, - 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'fatal' ->; - -export type LoggerFn = - | ((msg: string, ...args: any[]) => void) - | ((obj: object, msg?: string, ...args: any[]) => void); - -const isFirstArgObject = ( - args: Parameters, -): args is [obj: object, msg?: string, ...args: any[]] => - typeof args[0] === 'object'; - -export class ToplvlPinoLogger implements PinoMethods { - private context = ''; - - constructor( - private readonly contextName: string, - private readonly rootLogger: pino.Logger, - ) {} - - trace(msg: string, ...args: any[]): void; - trace(obj: unknown, msg?: string, ...args: any[]): void; - trace(...args: Parameters) { - this.call('trace', ...args); - } - - debug(msg: string, ...args: any[]): void; - debug(obj: unknown, msg?: string, ...args: any[]): void; - debug(...args: Parameters) { - this.call('debug', ...args); - } - - info(msg: string, ...args: any[]): void; - info(obj: unknown, msg?: string, ...args: any[]): void; - info(...args: Parameters) { - this.call('info', ...args); - } - - warn(msg: string, ...args: any[]): void; - warn(obj: unknown, msg?: string, ...args: any[]): void; - warn(...args: Parameters) { - this.call('warn', ...args); - } - - error(msg: string, ...args: any[]): void; - error(obj: unknown, msg?: string, ...args: any[]): void; - error(...args: Parameters) { - this.call('error', ...args); - } - - fatal(msg: string, ...args: any[]): void; - fatal(obj: unknown, msg?: string, ...args: any[]): void; - fatal(...args: Parameters) { - this.call('fatal', ...args); - } - - setContext(value: string) { - this.context = value; - } - - private call(method: pino.Level, ...args: Parameters) { - if (this.context && isFirstArgObject(args)) { - args = this.formatObjLog(method, ...args); - } else if (this.context) { - args = [ - { [this.contextName]: this.context }, - ...args, - ] as Parameters; - } - - // @ts-expect-error args are union of tuple types - this.rootLogger[method](...args); - } - - private formatObjLog( - method: pino.Level, - ...args: Parameters - ): Parameters { - const firstArg = args[0]; - - return [ - Object.assign( - { [this.contextName]: this.context }, - firstArg instanceof Error ? { err: firstArg } : firstArg, - ), - ...args.slice(1), - ]; - } -} diff --git a/src/starter/create-fastify-adapter.ts b/src/starter/create-fastify-adapter.ts deleted file mode 100644 index 47d389e..0000000 --- a/src/starter/create-fastify-adapter.ts +++ /dev/null @@ -1,30 +0,0 @@ -import { randomUUID } from 'node:crypto'; -import { FastifyAdapter } from '@nestjs/platform-fastify'; -import type { RawRequestDefaultExpression } from 'fastify'; - -export const createFastifyAdapter = ( - enableRequestId: boolean, -): FastifyAdapter => { - if (enableRequestId) { - return new FastifyAdapter({ - genReqId(req: RawRequestDefaultExpression) { - const fromHeaders = req.headersDistinct['x-request-id']; - - if ( - fromHeaders !== undefined && - fromHeaders.length > 0 && - fromHeaders[0] !== undefined - ) { - req.id = fromHeaders[0]; - return fromHeaders[0]; - } - - const id = randomUUID(); - req.id = id; - return id; - }, - }); - } else { - return new FastifyAdapter(); - } -}; diff --git a/src/starter/starter-app.ts b/src/starter/starter-app.ts index b24a753..f42342a 100644 --- a/src/starter/starter-app.ts +++ b/src/starter/starter-app.ts @@ -1,13 +1,11 @@ -import { setTimeout } from 'timers/promises'; -import type { INestApplication, Logger as NestLogger } from '@nestjs/common'; +import type { INestApplication } from '@nestjs/common'; import { ValidationPipe } from '@nestjs/common'; import { NestFactory } from '@nestjs/core'; import type { NestFastifyApplication } from '@nestjs/platform-fastify'; +import { FastifyAdapter } from '@nestjs/platform-fastify'; import { DocumentBuilder, SwaggerModule } from '@nestjs/swagger'; -import { Logger } from 'nestjs-pino'; import { setupGracefulShutdown } from '../modules/graceful-shutdown'; -import { createNestLogger, LOG_LEVEL } from '../modules/logging'; -import { createFastifyAdapter } from './create-fastify-adapter'; +import { LOG_LEVEL, StructuredLogger } from '../modules/logging'; import type { NestStarterConfig, SwaggerConfig } from './starter-config'; export const createStarterApp = async ( @@ -17,29 +15,28 @@ export const createStarterApp = async ( ): Promise => { // "bufferLogs: true" nestjs feature causes silent log issue. // instead create toplevel logger before app init - const logger = createNestLogger({ - level: LOG_LEVEL.TRACE, - prettyMode: process.env.NODE_ENV === 'development', - enableHttpTracing: false, - enableHttpRequestContext: false, + const logger = new StructuredLogger({ + config: { + level: LOG_LEVEL.VERBOSE, + prettyMode: process.env.NODE_ENV === 'development', + }, + dependencies: {}, }); - const app = await NestFactory.create( + return NestFactory.create( module, - createFastifyAdapter(true), + new FastifyAdapter(), { logger, }, ); - - return app; }; export const initStarterApp = async ( app: NestFastifyApplication, configClass: new () => T, ): Promise => { - const logger = app.get(Logger); + const logger = app.get(StructuredLogger); app.useLogger(logger); const config = app.get(configClass); @@ -47,7 +44,7 @@ export const initStarterApp = async ( app.enableShutdownHooks(); if (config.http.gracefulShutdown.enabled) { - await setupGracefulShutdown(app, logger as unknown as NestLogger); + await setupGracefulShutdown(app, logger); } // Should be here? @@ -72,15 +69,11 @@ export const startStarterApp = async ( configClass: new () => T, ): Promise => { const config = app.get(configClass); - const logger = app.get(Logger); + const logger = app.get(StructuredLogger); await app.listen(config.http.port, '0.0.0.0'); const appUrl = await app.getUrl(); - // ugly solution for pino logging stack issue - // toplevel logger is not working properly and ships logs with delay - await setTimeout(50); - logger.log(`Listening on ${appUrl}`, loggerContext); if (config.swagger.enabled) { diff --git a/src/starter/starter-config.ts b/src/starter/starter-config.ts index d56bcd5..89409cc 100644 --- a/src/starter/starter-config.ts +++ b/src/starter/starter-config.ts @@ -4,11 +4,11 @@ import { IsEnum, Max, Min } from 'class-validator'; import type { ActuatorModuleConfig } from '../modules/actuator'; import type { GracefulShutdownModuleConfig } from '../modules/graceful-shutdown'; import type { HealthcheckModuleConfig } from '../modules/healthcheck'; -import type { LoggerModuleConfig } from '../modules/logging'; +import type { LoggingModuleConfig } from '../modules/logging'; import { LOG_LEVEL } from '../modules/logging'; import type { PrometheusModuleConfig } from '../modules/prometheus'; -export class LoggingConfig implements LoggerModuleConfig { +export class LoggingConfig implements LoggingModuleConfig { @ConfigField() prettyMode!: boolean; diff --git a/src/starter/starter-modules.ts b/src/starter/starter-modules.ts index f1e474f..749fcab 100644 --- a/src/starter/starter-modules.ts +++ b/src/starter/starter-modules.ts @@ -1,8 +1,10 @@ -import { LoggerModule } from 'nestjs-pino'; +import { randomUUID } from 'node:crypto'; +import type { RawRequestDefaultExpression } from 'fastify'; +import { ClsModule } from 'nestjs-cls'; import { ActuatorModule, ActuatorService } from '../modules/actuator'; import { ConfigModule } from '../modules/config'; import { HealthcheckModule } from '../modules/healthcheck'; -import { createPinoHttpOpts } from '../modules/logging'; +import { LoggingModule } from '../modules/logging/logging.module'; import { PrometheusModule, PrometheusRegistry } from '../modules/prometheus'; import type { NestStarterConfig } from './starter-config'; @@ -46,14 +48,33 @@ export const createStarterModules = ( }, }), }), - LoggerModule.forRootAsync({ + ClsModule.forRoot({ + global: true, + middleware: { + mount: true, + generateId: true, + idGenerator: (req: RawRequestDefaultExpression) => { + const fromHeaders = req.headersDistinct['x-request-id']; + + if (fromHeaders !== undefined && fromHeaders[0] !== undefined) { + return fromHeaders[0]; + } + + return randomUUID(); + }, + }, + }), + LoggingModule.forRootAsync({ inject: [configClass, PrometheusRegistry], useFactory: ( { logging }: NestStarterConfig, - registry: PrometheusRegistry, + meterRegistry: PrometheusRegistry, ) => { return { - pinoHttp: createPinoHttpOpts(logging, registry), + config: logging, + dependencies: { + meterRegistry, + }, }; }, }), diff --git a/test/example-app/app.controller.ts b/test/example-app/app.controller.ts index 8ff232e..e9d5909 100644 --- a/test/example-app/app.controller.ts +++ b/test/example-app/app.controller.ts @@ -1,4 +1,9 @@ -import { Controller, Get, Logger } from '@nestjs/common'; +import { + Controller, + Get, + InternalServerErrorException, + Logger, +} from '@nestjs/common'; import { AppService } from './app.service'; @Controller('/') @@ -7,10 +12,20 @@ export class AppController { constructor(private service: AppService) {} - @Get('/hello') - getHello() { - this.logger.log('Hello World from controller!'); + @Get('/logging-test') + logging() { + this.logger.verbose('verbose log'); + this.logger.debug('debug log'); + this.logger.log('info log'); + this.logger.warn('warn log'); + this.logger.error('error log'); + this.logger.fatal('fatal log'); - return this.service.getHello(); + this.logger.log('userdata', { + id: 123, + something: 123123, + }); + + throw new InternalServerErrorException(new Error('asdads')); } } diff --git a/test/integration/exports.spec.ts b/test/integration/exports.spec.ts index ff9999a..bae8bfd 100644 --- a/test/integration/exports.spec.ts +++ b/test/integration/exports.spec.ts @@ -8,6 +8,7 @@ import { NestStarterConfig, PrometheusModule, startStarterApp, + StructuredLogger, } from '../../src'; describe('exports test', () => { @@ -21,5 +22,6 @@ describe('exports test', () => { expect(ConfigModule).toBeDefined(); expect(HealthcheckModule).toBeDefined(); expect(PrometheusModule).toBeDefined(); + expect(StructuredLogger).toBeDefined(); }); });