refactor(logger): improve readability and modularity (#33058)

Co-authored-by: Michael Kriese <michael.kriese@gmx.de>

lib/logger/index.spec.ts

 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' },

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);
 }
 
 /**

lib/logger/renovate-logger.ts

+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);
+    }
+  }
+}

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 : {};
+}