import type { WriteStream } from 'node:fs'; import bunyan from 'bunyan'; import fs from 'fs-extra'; import { DateTime } from 'luxon'; import { partial } from '~test/util.ts'; import { add } from '../util/host-rules.ts'; import { addSecretForSanitizing as addSecret } from '../util/sanitize.ts'; import { createDefaultStreams } from './bunyan.ts'; import { addMeta, addStream, clearProblems, getContext, getProblems, init, levels, logLevel, logger, removeMeta, setContext, setMeta, withMeta, } from './index.ts'; import { ProblemStream } from './problem-stream.ts'; import type { RenovateLogger } from './renovate-logger.ts'; const logContext = 'initial_context'; vi.unmock('./index.ts'); vi.mock('node:crypto', () => ({ randomUUID: vi.fn(() => 'initial_context'), })); const bunyanDebugSpy = vi.spyOn(bunyan.prototype, 'debug'); // init logger await init(); describe('logger/index', () => { beforeEach(() => { vi.stubEnv('LOG_FILE_LEVEL', undefined); }); it('inits', () => { expect(logger).toBeDefined(); }); it('uses an auto-generated log context', () => { logger.debug(''); expect(bunyanDebugSpy).toHaveBeenCalledExactlyOnceWith({ logContext }, ''); }); it('sets and gets context', () => { const logContext = '123test'; const msg = 'test'; setContext(logContext); logger.debug(msg); expect(getContext()).toBe(logContext); expect(bunyanDebugSpy).toHaveBeenCalledExactlyOnceWith({ logContext }, msg); }); it('supports logging with metadata', () => { expect(() => logger.debug({ some: 'meta' }, 'some meta')).not.toThrow(); }); it('supports logging with only metadata', () => { expect(() => logger.debug({ some: 'meta' })).not.toThrow(); }); it('supports logging without metadata', () => { expect(() => logger.debug('some meta')).not.toThrow(); }); describe('meta functions', () => { beforeEach(() => { setContext(logContext); setMeta({}); }); it('sets meta', () => { setMeta({ foo: 'foo' }); setMeta({ bar: 'bar' }); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenCalledExactlyOnceWith( { logContext, // `foo` key was rewritten bar: 'bar', baz: 'baz', }, 'message', ); expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); }); it('adds meta', () => { setMeta({ foo: 'foo' }); addMeta({ bar: 'bar' }); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenCalledExactlyOnceWith( { logContext, foo: 'foo', bar: 'bar', baz: 'baz', }, 'message', ); expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); }); it('removes meta', () => { setMeta({ foo: 'foo', bar: 'bar', }); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenCalledExactlyOnceWith( { logContext, foo: 'foo', bar: 'bar', baz: 'baz', }, 'message', ); expect(bunyanDebugSpy).toHaveBeenCalledTimes(1); removeMeta(['bar']); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenLastCalledWith( { logContext, foo: 'foo', baz: 'baz', }, 'message', ); expect(bunyanDebugSpy).toHaveBeenCalledTimes(2); }); it('withMeta adds and removes metadata correctly', () => { setMeta({ foo: 'foo' }); withMeta({ bar: 'bar' }, () => { logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenNthCalledWith( 1, { logContext, foo: 'foo', bar: 'bar', baz: 'baz', }, 'message', ); }); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenNthCalledWith( 2, { logContext, foo: 'foo', baz: 'baz', }, 'message', ); }); it('withMeta handles cleanup when callback throws', () => { setMeta({ foo: 'foo' }); expect(() => withMeta({ bar: 'bar' }, () => { logger.debug({ baz: 'baz' }, 'message'); throw new Error('test error'); }), ).toThrow('test error'); logger.debug({ baz: 'baz' }, 'message'); expect(bunyanDebugSpy).toHaveBeenNthCalledWith( 2, { logContext, foo: 'foo', baz: 'baz', }, 'message', ); }); }); describe('createDefaultStreams', () => { beforeEach(() => { vi.stubEnv('LOG_FILE_FORMAT', undefined); }); it('creates log file stream', () => { expect( createDefaultStreams('info', new ProblemStream(), 'file.log'), ).toMatchObject([ { name: 'stdout', type: 'raw' }, { name: 'problems', type: 'raw' }, { name: 'logfile' }, ]); }); it.each([ { logFileLevel: null, expectedLogLevel: 'debug', }, { logFileLevel: 'warn', expectedLogLevel: 'warn', }, ])( 'handles log file stream $logFileLevel level', ({ logFileLevel, expectedLogLevel }) => { if (logFileLevel !== null) { vi.stubEnv('LOG_FILE_LEVEL', logFileLevel?.toString()); } const streams = createDefaultStreams( 'info', new ProblemStream(), 'file.log', ); const logFileStream = streams[2]; expect(logFileStream.level).toBe(expectedLogLevel); }, ); it.each([ { logFileFormat: 'json', expectedType: undefined, }, { logFileFormat: 'pretty', expectedType: 'raw', }, ])( 'handles log file stream $logFileFormat format', ({ logFileFormat, expectedType }) => { vi.stubEnv('LOG_FILE_FORMAT', logFileFormat); const streams = createDefaultStreams( 'info', new ProblemStream(), 'file.log', ); const logFileStream = streams[2]; expect(logFileStream.type).toBe(expectedType); }, ); it('writes pretty formatted data synchronously to log file', async () => { vi.stubEnv('LOG_FILE_FORMAT', 'pretty'); const streams = createDefaultStreams( 'info', new ProblemStream(), 'file.log', ); const logFileStream = streams[2]; const stream = logFileStream.stream as { write: (...args: unknown[]) => void; }; stream.write({ level: 30, msg: 'test message' }); await expect(fs.readFile('file.log', 'utf8')).resolves.toContain( 'test message', ); }); it('writes json data synchronously to log file', async () => { const streams = createDefaultStreams( 'info', new ProblemStream(), 'file.log', ); const logFileStream = streams[2]; const stream = logFileStream.stream as { write: (...args: unknown[]) => void; }; stream.write('{"level":30,"msg":"json message"}\n'); await expect(fs.readFile('file.log', 'utf8')).resolves.toContain( 'json message', ); }); }); it('sets level', () => { expect(logLevel()).toBeDefined(); // depends on passed env expect(() => levels('stdout', 'debug')).not.toThrow(); expect(logLevel()).toBe('debug'); }); it('should create a child logger', () => { const childLogger = (logger as RenovateLogger).childLogger(); const loggerSpy = vi.spyOn(logger, 'debug'); const childLoggerSpy = vi.spyOn(childLogger, 'debug'); childLogger.debug('test'); expect(loggerSpy).toHaveBeenCalledTimes(0); expect(childLoggerSpy).toHaveBeenCalledTimes(1); expect(childLoggerSpy).toHaveBeenCalledExactlyOnceWith('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' }, { msg: 'a warning with a **redacted**' }, ]); clearProblems(); expect(getProblems()).toHaveLength(0); }); it('should contain path or stream parameters', () => { expect(() => addStream({ name: 'logfile', level: 'error', }), ).toThrow("Missing 'stream' or 'path' for bunyan stream"); }); it("doesn't support rotating files", () => { expect(() => addStream({ name: 'logfile', path: 'file.log', level: 'error', type: 'rotating-file', }), ).toThrow("Rotating files aren't supported"); }); it('supports file-based logging', () => { let chunk = ''; vi.spyOn(fs, 'createWriteStream').mockReturnValueOnce( partial({ writable: true, write(x: string): boolean { chunk = x; return true; }, }), ); addStream({ name: 'logfile', path: 'file.log', level: 'error', }); logger.error('foo'); expect(JSON.parse(chunk).msg).toBe('foo'); }); it('handles cycles', () => { let logged: Record = {}; vi.spyOn(fs, 'createWriteStream').mockReturnValueOnce( partial({ writable: true, write(x: string): boolean { logged = JSON.parse(x); return true; }, }), ); addStream({ name: 'logfile', path: 'file.log', level: 'error', }); const meta: Record = { foo: null, bar: [] }; meta.foo = meta; meta.bar.push(meta); logger.error(meta, 'foo'); expect(logged.msg).toBe('foo'); expect(logged.foo.foo).toBe('[Circular]'); expect(logged.foo.bar).toEqual(['[Circular]']); expect(logged.bar).toEqual([ { bar: '[Circular]', foo: '[Circular]', }, ]); }); it('sanitizes secrets', () => { let logged: Record = {}; vi.spyOn(fs, 'createWriteStream').mockReturnValueOnce( partial({ writable: true, write(x: string): boolean { logged = JSON.parse(x); return true; }, }), ); addStream({ name: 'logfile', path: 'file.log', level: 'error', }); add({ password: 'secret"password' }); class SomeClass { public field: string; constructor(field: string) { this.field = field; } } const prBody = 'test'; logger.error({ foo: 'secret"password', bar: ['somethingelse', 'secret"password'], npmToken: 'token', buffer: Buffer.from('test'), content: 'test', prBody, secrets: { foo: 'barsecret', }, someFn: () => 'secret"password', someObject: new SomeClass('secret"password'), }); expect(logged.foo).not.toBe('secret"password'); expect(logged.bar[0]).toBe('somethingelse'); expect(logged.foo).toContain('redacted'); expect(logged.bar[1]).toContain('redacted'); expect(logged.npmToken).not.toBe('token'); expect(logged.buffer).toBe('[content]'); expect(logged.content).toBe('[content]'); expect(logged.prBody).toBe(prBody); expect(logged.secrets.foo).toBe('***********'); expect(logged.someFn).toBe('[function]'); expect(logged.someObject.field).toBe('**redacted**'); }); it('applies custom serializer while keeping default sanitizers', () => { let logged: Record = {}; vi.spyOn(fs, 'createWriteStream').mockReturnValueOnce( partial({ writable: true, write(x: string): boolean { logged = JSON.parse(x); return true; }, }), ); addStream({ name: 'logfile', path: 'file.log', level: 'error', }); add({ password: 'secret"password' }); class SomeClass { public field: string; constructor(field: string) { this.field = field; } } const childLogger = (logger as RenovateLogger).childLogger(); childLogger.addSerializers({ baz: (baz: string): any => { return `baz custom serializer: ${baz}`; }, }); const prBody = 'test'; childLogger.error({ foo: 'secret"password', bar: ['somethingelse', 'secret"password'], baz: 'baz', npmToken: 'token', buffer: Buffer.from('test'), content: 'test', prBody, secrets: { foo: 'barsecret', }, someDate: new Date('2021-04-05T06:07Z'), someFn: () => 'secret"password', someLuxonDate: DateTime.fromISO('2020-02-29'), someLuxonDateTime: DateTime.fromISO('2020-02-29T01:40:21.345+00:00'), someObject: new SomeClass('secret"password'), }); expect(logged.baz).toContain('baz custom serializer: baz'); expect(logged.foo).not.toBe('secret"password'); expect(logged.bar[0]).toBe('somethingelse'); expect(logged.foo).toContain('redacted'); expect(logged.bar[1]).toContain('redacted'); expect(logged.npmToken).not.toBe('token'); expect(logged.buffer).toBe('[content]'); expect(logged.content).toBe('[content]'); expect(logged.prBody).toBe(prBody); expect(logged.secrets.foo).toBe('***********'); expect(logged.someDate).toBe('2021-04-05T06:07:00.000Z'); expect(logged.someFn).toBe('[function]'); expect(logged.someLuxonDate).toBe('2020-02-29T00:00:00.000+00:00'); expect(logged.someLuxonDateTime).toBe('2020-02-29T01:40:21.345+00:00'); expect(logged.someObject.field).toBe('**redacted**'); }); it('sanitizes secrets in object keys', () => { let logged: Record = {}; vi.spyOn(fs, 'createWriteStream').mockReturnValueOnce( partial({ writable: true, write(x: string): boolean { logged = JSON.parse(x); return true; }, }), ); addStream({ name: 'logfile', path: 'file.log', level: 'debug', }); const secret = 'https://secret@example.com'; const data: Record = { [secret]: { nested: secret }, }; logger.debug( { data, secret, }, 'logs secrets in keys', ); expect(logged.data).toStrictEqual({ 'https://**redacted**@example.com': { nested: 'https://**redacted**@example.com', }, }); expect(logged.secret).toBe('https://**redacted**@example.com'); }); });