diff options
| -rw-r--r-- | lib/logger/index.spec.ts | 105 | ||||
| -rw-r--r-- | lib/logger/index.ts | 192 | ||||
| -rw-r--r-- | lib/logger/renovate-logger.ts | 156 | ||||
| -rw-r--r-- | lib/logger/utils.ts | 13 |
4 files changed, 339 insertions, 127 deletions
diff --git a/lib/logger/index.spec.ts b/lib/logger/index.spec.ts index a2eb3e3beb1..6fc7c67dead 100644 --- a/lib/logger/index.spec.ts +++ b/lib/logger/index.spec.ts @@ -1,8 +1,10 @@ import type { WriteStream } from 'node:fs'; +import bunyan from 'bunyan'; import fs from 'fs-extra'; import { partial } from '../../test/util'; import { add } from '../util/host-rules'; import { addSecretForSanitizing as addSecret } from '../util/sanitize'; +import type { RenovateLogger } from './renovate-logger'; import { addMeta, addStream, @@ -17,16 +19,38 @@ import { setMeta, } from '.'; +const initialContext = 'initial_context'; + jest.unmock('.'); +jest.mock('nanoid', () => ({ + nanoid: () => 'initial_context', +})); + +const bunyanDebugSpy = jest.spyOn(bunyan.prototype, 'debug'); describe('logger/index', () => { it('inits', () => { expect(logger).toBeDefined(); }); + it('uses an auto-generated log context', () => { + logger.debug(''); + + expect(bunyanDebugSpy).toHaveBeenCalledWith( + { logContext: initialContext }, + '', + ); + }); + it('sets and gets context', () => { - setContext('123test'); - expect(getContext()).toBe('123test'); + const logContext = '123test'; + const msg = 'test'; + setContext(logContext); + + logger.debug(msg); + + expect(getContext()).toBe(logContext); + expect(bunyanDebugSpy).toHaveBeenCalledWith({ logContext }, msg); }); it('supports logging with metadata', () => { @@ -41,16 +65,62 @@ describe('logger/index', () => { expect(() => logger.debug('some meta')).not.toThrow(); }); - it('sets meta', () => { - expect(() => setMeta({ any: 'test' })).not.toThrow(); - }); + describe('meta functions', () => { + beforeEach(() => { + setContext(initialContext); + }); - it('adds meta', () => { - expect(() => addMeta({ new: 'test' })).not.toThrow(); - }); + it('sets meta', () => { + const logMeta = { foo: 'foo' }; + const meta = { bar: 'bar' }; + setMeta(meta); + + logger.debug(logMeta, ''); + + expect(bunyanDebugSpy).toHaveBeenCalledWith( + { logContext: initialContext, ...meta, ...logMeta }, + '', + ); + expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); + }); - it('removes meta', () => { - expect(() => removeMeta(['new'])).not.toThrow(); + it('adds meta', () => { + const logMeta = { foo: 'foo' }; + const meta = { bar: 'bar' }; + addMeta(meta); + + logger.debug(logMeta, ''); + + expect(bunyanDebugSpy).toHaveBeenCalledWith( + { logContext: initialContext, ...meta, ...logMeta }, + '', + ); + expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); + }); + + it('removes meta', () => { + const logMeta = { foo: 'foo' }; + const meta = { bar: 'bar' }; + setMeta(meta); + + logger.debug(logMeta, ''); + + expect(bunyanDebugSpy).toHaveBeenCalledWith( + { logContext: initialContext, ...meta, ...logMeta }, + '', + ); + expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); + + removeMeta(Object.keys(meta)); + + logger.debug(logMeta, ''); + + expect(bunyanDebugSpy).toHaveBeenCalledWith( + { logContext: initialContext, ...logMeta }, + '', + ); + expect(bunyanDebugSpy).toHaveBeenCalledTimes(2); + }); }); it('sets level', () => { @@ -59,15 +129,30 @@ describe('logger/index', () => { expect(logLevel()).toBe('debug'); }); + it('should create a child logger', () => { + const childLogger = (logger as RenovateLogger).childLogger(); + const loggerSpy = jest.spyOn(logger, 'debug'); + const childLoggerSpy = jest.spyOn(childLogger, 'debug'); + + childLogger.debug('test'); + + expect(loggerSpy).toHaveBeenCalledTimes(0); + expect(childLoggerSpy).toHaveBeenCalledTimes(1); + expect(childLoggerSpy).toHaveBeenCalledWith('test'); + }); + it('saves problems', () => { addSecret('p4$$w0rd'); levels('stdout', 'fatal'); + logger.fatal('fatal error'); logger.error('some meta'); logger.error({ some: 'meta', password: 'super secret' }); logger.error({ some: 'meta' }, 'message'); logger.warn('a warning with a p4$$w0rd'); + logger.trace('ignored'); logger.info('ignored'); expect(getProblems()).toMatchObject([ + { msg: 'fatal error' }, { msg: 'some meta' }, { some: 'meta', password: '***********' }, { some: 'meta', msg: 'message' }, diff --git a/lib/logger/index.ts b/lib/logger/index.ts index f066e05f97b..a120c4a4584 100644 --- a/lib/logger/index.ts +++ b/lib/logger/index.ts @@ -6,9 +6,8 @@ import upath from 'upath'; import cmdSerializer from './cmd-serializer'; import configSerializer from './config-serializer'; import errSerializer from './err-serializer'; -import { once, reset as onceReset } from './once'; import { RenovateStream } from './pretty-stdout'; -import { getRemappedLevel } from './remap'; +import { RenovateLogger } from './renovate-logger'; import type { BunyanRecord, Logger } from './types'; import { ProblemStream, @@ -17,161 +16,120 @@ import { withSanitizer, } from './utils'; -let logContext: string = getEnv('LOG_CONTEXT') ?? nanoid(); -let curMeta: Record<string, unknown> = {}; - const problems = new ProblemStream(); - let stdoutLevel = validateLogLevel(getEnv('LOG_LEVEL'), 'info'); -const stdout: bunyan.Stream = { - name: 'stdout', - level: stdoutLevel, - stream: process.stdout, -}; export function logLevel(): bunyan.LogLevelString { return stdoutLevel; } -// istanbul ignore if: not testable -if (getEnv('LOG_FORMAT') !== 'json') { - // TODO: typings (#9615) - const prettyStdOut = new RenovateStream() as any; - prettyStdOut.pipe(process.stdout); - stdout.stream = prettyStdOut; - stdout.type = 'raw'; -} - -const bunyanLogger = bunyan.createLogger({ - name: 'renovate', - serializers: { - body: configSerializer, - cmd: cmdSerializer, - config: configSerializer, - migratedConfig: configSerializer, - originalConfig: configSerializer, - presetConfig: configSerializer, - oldConfig: configSerializer, - newConfig: configSerializer, - err: errSerializer, - }, - streams: [ - stdout, - { - name: 'problems', - level: 'warn' as bunyan.LogLevel, - stream: problems as any, - type: 'raw', - }, - ].map(withSanitizer), -}); - -const logFactory = ( - _level: bunyan.LogLevelString, -): ((p1: unknown, p2: unknown) => void) => { - return (p1: any, p2: any): void => { - let level = _level; - if (p2) { - // meta and msg provided - const msg = p2; - const meta: Record<string, unknown> = { logContext, ...curMeta, ...p1 }; - const remappedLevel = getRemappedLevel(msg); - // istanbul ignore if: not testable - if (remappedLevel) { - meta.oldLevel = level; - level = remappedLevel; - } - bunyanLogger[level](meta, msg); - } else if (is.string(p1)) { - // only message provided - const msg = p1; - const meta: Record<string, unknown> = { logContext, ...curMeta }; - const remappedLevel = getRemappedLevel(msg); - // istanbul ignore if: not testable - if (remappedLevel) { - meta.oldLevel = level; - level = remappedLevel; - } - bunyanLogger[level](meta, msg); - } else { - // only meta provided - bunyanLogger[level]({ logContext, ...curMeta, ...p1 }); - } +export function createDefaultStreams( + stdoutLevel: bunyan.LogLevelString, + problems: ProblemStream, + logFile: string | undefined, +): bunyan.Stream[] { + const stdout: bunyan.Stream = { + name: 'stdout', + level: stdoutLevel, + stream: process.stdout, }; -}; - -const loggerLevels: bunyan.LogLevelString[] = [ - 'trace', - 'debug', - 'info', - 'warn', - 'error', - 'fatal', -]; - -export const logger: Logger = { once: { reset: onceReset } } as any; - -loggerLevels.forEach((loggerLevel) => { - logger[loggerLevel] = logFactory(loggerLevel) as never; - - const logOnceFn = (p1: any, p2: any): void => { - once(() => { - const logFn = logger[loggerLevel]; - if (is.undefined(p2)) { - logFn(p1); - } else { - logFn(p1, p2); - } - }, logOnceFn); + + // istanbul ignore if: not testable + if (getEnv('LOG_FORMAT') !== 'json') { + // TODO: typings (#9615) + const prettyStdOut = new RenovateStream() as any; + prettyStdOut.pipe(process.stdout); + stdout.stream = prettyStdOut; + stdout.type = 'raw'; + } + + const problemsStream: bunyan.Stream = { + name: 'problems', + level: 'warn' as bunyan.LogLevel, + stream: problems as any, + type: 'raw', }; - logger.once[loggerLevel] = logOnceFn as never; -}); -const logFile = getEnv('LOG_FILE'); -// istanbul ignore if: not easily testable -if (is.string(logFile)) { - // ensure log file directory exists + // istanbul ignore next: not easily testable + const logFileStream: bunyan.Stream | undefined = is.string(logFile) + ? createLogFileStream(logFile) + : undefined; + + return [stdout, problemsStream, logFileStream].filter( + Boolean, + ) as bunyan.Stream[]; +} + +// istanbul ignore next: not easily testable +function createLogFileStream(logFile: string): bunyan.Stream { + // Ensure log file directory exists const directoryName = upath.dirname(logFile); fs.ensureDirSync(directoryName); - addStream({ + return { name: 'logfile', path: logFile, level: validateLogLevel(getEnv('LOG_FILE_LEVEL'), 'debug'), + }; +} + +function serializedSanitizedLogger(streams: bunyan.Stream[]): bunyan { + return bunyan.createLogger({ + name: 'renovate', + serializers: { + body: configSerializer, + cmd: cmdSerializer, + config: configSerializer, + migratedConfig: configSerializer, + originalConfig: configSerializer, + presetConfig: configSerializer, + oldConfig: configSerializer, + newConfig: configSerializer, + err: errSerializer, + }, + streams: streams.map(withSanitizer), }); } +const defaultStreams = createDefaultStreams( + stdoutLevel, + problems, + getEnv('LOG_FILE'), +); + +const bunyanLogger = serializedSanitizedLogger(defaultStreams); +const logContext = getEnv('LOG_CONTEXT') ?? nanoid(); +const loggerInternal = new RenovateLogger(bunyanLogger, logContext, {}); + +export const logger: Logger = loggerInternal; + export function setContext(value: string): void { - logContext = value; + loggerInternal.logContext = value; } export function getContext(): any { - return logContext; + return loggerInternal.logContext; } // setMeta overrides existing meta, may remove fields if no longer existing export function setMeta(obj: Record<string, unknown>): void { - curMeta = { ...obj }; + loggerInternal.setMeta(obj); } // addMeta overrides or adds fields but does not remove any export function addMeta(obj: Record<string, unknown>): void { - curMeta = { ...curMeta, ...obj }; + loggerInternal.addMeta(obj); } // removeMeta removes the provided fields from meta export function removeMeta(fields: string[]): void { - Object.keys(curMeta).forEach((key) => { - if (fields.includes(key)) { - delete curMeta[key]; - } - }); + loggerInternal.removeMeta(fields); } export /* istanbul ignore next */ function addStream( stream: bunyan.Stream, ): void { - bunyanLogger.addStream(withSanitizer(stream)); + loggerInternal.addStream(stream); } /** diff --git a/lib/logger/renovate-logger.ts b/lib/logger/renovate-logger.ts new file mode 100644 index 00000000000..096b763ec42 --- /dev/null +++ b/lib/logger/renovate-logger.ts @@ -0,0 +1,156 @@ +import is from '@sindresorhus/is'; +import type * as bunyan from 'bunyan'; +import { once, reset as onceReset } from './once'; +import { getRemappedLevel } from './remap'; +import type { Logger } from './types'; +import { getMessage, toMeta, withSanitizer } from './utils'; + +const loggerLevels: bunyan.LogLevelString[] = [ + 'trace', + 'debug', + 'info', + 'warn', + 'error', + 'fatal', +]; + +type LoggerFunction = (p1: string | Record<string, any>, p2?: string) => void; + +export class RenovateLogger implements Logger { + readonly logger: Logger = { once: { reset: onceReset } } as any; + readonly once = this.logger.once; + + constructor( + private readonly bunyanLogger: bunyan, + private context: string, + private meta: Record<string, unknown>, + ) { + for (const level of loggerLevels) { + this.logger[level] = this.logFactory(level) as never; + this.logger.once[level] = this.logOnceFn(level); + } + } + + trace(p1: string): void; + trace(p1: Record<string, any>, p2?: string): void; + trace(p1: string | Record<string, any>, p2?: string): void { + this.log('trace', p1, p2); + } + + debug(p1: string): void; + debug(p1: Record<string, any>, p2?: string): void; + debug(p1: string | Record<string, any>, p2?: string): void { + this.log('debug', p1, p2); + } + + info(p1: string): void; + info(p1: Record<string, any>, p2?: string): void; + info(p1: string | Record<string, any>, p2?: string): void { + this.log('info', p1, p2); + } + + warn(p1: string): void; + warn(p1: Record<string, any>, p2?: string): void; + warn(p1: string | Record<string, any>, p2?: string): void { + this.log('warn', p1, p2); + } + + error(p1: string): void; + error(p1: Record<string, any>, p2?: string): void; + error(p1: string | Record<string, any>, p2?: string): void { + this.log('error', p1, p2); + } + + fatal(p1: string): void; + fatal(p1: Record<string, any>, p2?: string): void; + fatal(p1: string | Record<string, any>, p2?: string): void { + this.log('fatal', p1, p2); + } + + addStream(stream: bunyan.Stream): void { + this.bunyanLogger.addStream(withSanitizer(stream)); + } + + childLogger(): RenovateLogger { + return new RenovateLogger( + this.bunyanLogger.child({}), + this.context, + this.meta, + ); + } + + get logContext(): string { + return this.context; + } + + set logContext(context: string) { + this.context = context; + } + + setMeta(obj: Record<string, unknown>): void { + this.meta = { ...obj }; + } + + addMeta(obj: Record<string, unknown>): void { + this.meta = { ...this.meta, ...obj }; + } + + removeMeta(fields: string[]): void { + for (const key of Object.keys(this.meta)) { + if (fields.includes(key)) { + delete this.meta[key]; + } + } + } + + private logFactory(_level: bunyan.LogLevelString): LoggerFunction { + return (p1: string | Record<string, any>, p2?: string): void => { + const meta: Record<string, unknown> = { + logContext: this.context, + ...this.meta, + ...toMeta(p1), + }; + const msg = getMessage(p1, p2); + let level = _level; + + if (is.string(msg)) { + const remappedLevel = getRemappedLevel(msg); + // istanbul ignore if: not easily testable + if (remappedLevel) { + meta.oldLevel = level; + level = remappedLevel; + } + this.bunyanLogger[level](meta, msg); + } else { + this.bunyanLogger[level](meta); + } + }; + } + + private logOnceFn(level: bunyan.LogLevelString): LoggerFunction { + const logOnceFn = (p1: string | Record<string, any>, p2?: string): void => { + once(() => { + const logFn = this[level].bind(this); // bind to the instance. + if (is.string(p1)) { + logFn(p1); + } else { + logFn(p1, p2); + } + }, logOnceFn); + }; + return logOnceFn; + } + + private log( + level: bunyan.LogLevelString, + p1: string | Record<string, any>, + p2?: string, + ): void { + const logFn = this.logger[level]; + if (is.string(p1)) { + logFn(p1); + } else { + logFn(p1, p2); + } + } +} diff --git a/lib/logger/utils.ts b/lib/logger/utils.ts index 5b2d512601a..b85f2c44de2 100644 --- a/lib/logger/utils.ts +++ b/lib/logger/utils.ts @@ -339,3 +339,16 @@ export function getEnv(key: string): string | undefined { .map((v) => v?.toLowerCase().trim()) .find(is.nonEmptyStringAndNotWhitespace); } + +export function getMessage( + p1: string | Record<string, any>, + p2?: string, +): string | undefined { + return is.string(p1) ? p1 : p2; +} + +export function toMeta( + p1: string | Record<string, any>, +): Record<string, unknown> { + return is.object(p1) ? p1 : {}; +} |