diff --git a/packages/backend-lib/src/server/logMiddleware.test.ts b/packages/backend-lib/src/server/logMiddleware.test.ts new file mode 100644 index 000000000..0d3297309 --- /dev/null +++ b/packages/backend-lib/src/server/logMiddleware.test.ts @@ -0,0 +1,99 @@ +import { commonLoggerCreate } from '@naturalcycles/js-lib/log' +import type { AnyObject } from '@naturalcycles/js-lib/types' +import { afterEach, beforeEach, expect, test, vi } from 'vitest' +import { devLogger, gcpStructuredLogger } from './logMiddleware.js' + +let calls: any[][] + +beforeEach(() => { + calls = [] + vi.spyOn(console, 'log').mockImplementation((...args: any[]) => { + calls.push(args) + }) +}) + +afterEach(() => { + vi.restoreAllMocks() +}) + +test('gcpStructuredLogger writes the log entry as structured fields', () => { + commonLoggerCreate(gcpStructuredLogger, { accountId: 'a1' }).warn('hello', { n: 1 }) + + expect(calls).toHaveLength(1) + expect(calls[0]).toHaveLength(1) + expect(JSON.parse(calls[0]![0])).toStrictEqual({ + accountId: 'a1', + n: 1, + message: 'hello', + severity: 'WARNING', + }) +}) + +test('the log entry cannot override meta', () => { + commonLoggerCreate(gcpStructuredLogger, { severity: 'nope' }).error('x') + + expect(JSON.parse(calls[0]![0])).toStrictEqual({ + message: 'x', + severity: 'ERROR', + }) +}) + +test('gcpStructuredLogger with a single string argument', () => { + gcpStructuredLogger.log('plain') + + expect(JSON.parse(calls[0]![0])).toStrictEqual({ + message: 'plain', + }) +}) + +test('gcpStructuredLogger with multiple arguments', () => { + gcpStructuredLogger.log('a', { b: 1 }) + + expect(JSON.parse(calls[0]![0])).toStrictEqual({ + message: 'a { b: 1 }', + }) +}) + +test('gcpStructuredLogger keeps the error stack in message', () => { + commonLoggerCreate(gcpStructuredLogger, {}).error('failed', new Error('kaboom')) + + const entry = JSON.parse(calls[0]![0]) + expect(entry.message).toMatch(/^failed\n/) + expect(entry.message).toContain('kaboom') + expect(entry.message).toContain(' at ') + expect(entry.err).toEqual( + expect.objectContaining({ name: 'Error', message: 'kaboom', stack: expect.any(String) }), + ) +}) + +test('gcpStructuredLogger keeps a message field, msg wins over it', () => { + const logger = commonLoggerCreate(gcpStructuredLogger, {}) + + logger.log({ message: 'x' }) + logger.log({ message: 'x' }, 'y') + + expect(JSON.parse(calls[0]![0])).toStrictEqual({ message: 'x' }) + expect(JSON.parse(calls[1]![0])).toStrictEqual({ message: 'y' }) +}) + +test('gcpStructuredLogger survives a circular value', () => { + const circular: AnyObject = { n: 1 } + circular['self'] = circular + + commonLoggerCreate(gcpStructuredLogger, {}).log('hello', { circular }) + + const entry = JSON.parse(calls[0]![0]) + expect(entry.message).toBe('hello') + expect(entry.circular.n).toBe(1) + expect(entry.circular.self).toContain('Circular') +}) + +test('devLogger prints the log entry', () => { + commonLoggerCreate(devLogger, { accountId: 'a1' }).log('hello', { n: 1 }) + + expect(calls).toHaveLength(1) + const output = calls[0]![0] as string + expect(output).toContain('hello') + expect(output).toContain('accountId') + expect(output).toContain('n') +}) diff --git a/packages/backend-lib/src/server/logMiddleware.ts b/packages/backend-lib/src/server/logMiddleware.ts index 4a58efe72..7de89bb16 100644 --- a/packages/backend-lib/src/server/logMiddleware.ts +++ b/packages/backend-lib/src/server/logMiddleware.ts @@ -1,5 +1,8 @@ import { inspect } from 'node:util' +import { _isPlainObject } from '@naturalcycles/js-lib' +import { _anyToErrorObject } from '@naturalcycles/js-lib/error' import type { CommonLogger } from '@naturalcycles/js-lib/log' +import { _safeJsonStringify } from '@naturalcycles/js-lib/string/safeJsonStringify.js' import { _objectAssign } from '@naturalcycles/js-lib/types' import type { AnyObject } from '@naturalcycles/js-lib/types' import { _inspect } from '@naturalcycles/nodejs-lib' @@ -50,22 +53,46 @@ export const ciLogger: CommonLogger = { // Documented here: https://cloud.google.com/logging/docs/structured-logging // Cloud Run logging: https://cloud.google.com/run/docs/logging function writeGCPStructuredLog(meta: AnyObject, args: any[]): void { - console.log( - JSON.stringify({ - message: args.map(a => (typeof a === 'string' ? a : inspect(a))).join(' '), - ...meta, - }), - ) + if (args.length !== 1 || !_isPlainObject(args[0])) { + console.log( + JSON.stringify({ + message: args.map(a => (typeof a === 'string' ? a : inspect(a))).join(' '), + ...meta, + }), + ) + return + } + + const { msg, err, ...entry } = args[0] + if (err instanceof Error) { + entry['err'] = _anyToErrorObject(err) + entry['message'] = msg ? `${msg}\n${inspect(err)}` : inspect(err) + } else { + if (err !== undefined) entry['err'] = err + if (msg !== undefined) entry['message'] = msg + } + console.log(_safeJsonStringify({ ...entry, ...meta })) } function logToDev(requestId: string | null, args: any[]): void { // Run on local machine - console.log( - [ - requestId ? [dimGrey(`[${requestId}]`)] : [], - ...args.map(a => _inspect(a, { includeErrorStack: true, colors: true })), - ].join(' '), - ) + if (args.length !== 1 || !_isPlainObject(args[0])) { + console.log( + [ + requestId ? [dimGrey(`[${requestId}]`)] : [], + ...args.map(a => _inspect(a, { includeErrorStack: true, colors: true })), + ].join(' '), + ) + return + } + + const { msg, err, ...rest } = args[0] + const parts: string[] = [] + if (requestId) parts.push(dimGrey(`[${requestId}]`)) + if (msg !== undefined) parts.push(String(msg)) + if (err !== undefined) parts.push(_inspect(err, { includeErrorStack: true, colors: true })) + if (Object.keys(rest).length) parts.push(dimGrey(_inspect(rest, { colors: false }))) + console.log(parts.join(' ')) } /** diff --git a/packages/js-lib/src/is.util.test.ts b/packages/js-lib/src/is.util.test.ts index 301e839b0..5a9473f67 100644 --- a/packages/js-lib/src/is.util.test.ts +++ b/packages/js-lib/src/is.util.test.ts @@ -8,6 +8,7 @@ import { _isNotEmptyObject, _isNull, _isObject, + _isPlainObject, _isPrimitive, _isTruthy, } from './is.util.js' @@ -73,6 +74,30 @@ test('_isObject', () => { expect(_isObject(new Obj())).toBe(true) }) +test('_isPlainObject', () => { + expect(_isPlainObject({})).toBe(true) + expect(_isPlainObject({ a: 1 })).toBe(true) + expect(_isPlainObject(Object.create(null))).toBe(true) + + class Obj {} + + const a: any[] = [ + [], + null, + undefined, + 's', + 1, + new Error('e'), + new Date(), + new Obj(), + /re/, + () => {}, + ] + for (const v of a) { + expect(_isPlainObject(v)).toBe(false) + } +}) + test('_isEmptyObject', () => { const a: any[] = [{}, { a: 'b' }] diff --git a/packages/js-lib/src/is.util.ts b/packages/js-lib/src/is.util.ts index 99d07c9b6..759fbd11b 100644 --- a/packages/js-lib/src/is.util.ts +++ b/packages/js-lib/src/is.util.ts @@ -1,4 +1,4 @@ -import type { AnyObject, FalsyValue, NullishValue, Primitive } from './types.js' +import type { AnyObject, FalsyValue, NullishValue, PlainObject, Primitive } from './types.js' type Nullish = T extends NullishValue ? T : never type Truthy = T extends FalsyValue ? never : T @@ -32,6 +32,15 @@ export function _isObject(obj: any): obj is AnyObject { return (typeof obj === 'object' && obj !== null && !Array.isArray(obj)) || false } +/** + * Returns true if item is an object literal: not an Array, Error, RegExp or class instance. + */ +export function _isPlainObject(v: any): v is PlainObject { + if (typeof v !== 'object' || v === null) return false + const proto = Object.getPrototypeOf(v) + return proto === Object.prototype || proto === null +} + export function _isPrimitive(v: any): v is Primitive { return ( v === null || diff --git a/packages/js-lib/src/log/commonLogger.test.ts b/packages/js-lib/src/log/commonLogger.test.ts index 6e55e1185..0f6b50dd2 100644 --- a/packages/js-lib/src/log/commonLogger.test.ts +++ b/packages/js-lib/src/log/commonLogger.test.ts @@ -1,5 +1,6 @@ -import { test } from 'vitest' -import type { CommonLogger, CommonLogWithLevelFunction } from './commonLogger.js' +import { expect, test } from 'vitest' +import type { AnyObject } from '../types.js' +import type { CommonLogger, CommonLogLevel, CommonLogWithLevelFunction } from './commonLogger.js' import { commonLoggerCreate, commonLoggerNoop, @@ -49,3 +50,121 @@ test('commonLoggerCreate', () => { logger.log('hey') logger.error('hey') }) + +test('commonLoggerCreate accepts a CommonLogger as a sink', () => { + const { logger, calls } = createTestSink() + + commonLoggerCreate(logger).log('a', 1) + + expect(calls).toStrictEqual([['log', ['a', 1]]]) +}) + +test('a context makes every call emit a single object', () => { + const { logger, calls } = createTestSink() + const contextLogger = commonLoggerCreate(logger, { a: 1 }) + + contextLogger.debug('hey') + contextLogger.log('hey') + contextLogger.warn('hey') + contextLogger.error('hey') + + expect(calls).toStrictEqual([ + ['debug', [{ a: 1, msg: 'hey' }]], + ['log', [{ a: 1, msg: 'hey' }]], + ['warn', [{ a: 1, msg: 'hey' }]], + ['error', [{ a: 1, msg: 'hey' }]], + ]) +}) + +test('child merges the context, child keys win', () => { + const { logger, calls } = createTestSink() + const parent = commonLoggerCreate(logger, { a: 1 }) + const child = parent.child({ b: 2, a: 9 }) + + child.debug('foo') + parent.debug('foo') + child.child({ c: 3 }).debug('foo') + + expect(calls).toStrictEqual([ + ['debug', [{ a: 9, b: 2, msg: 'foo' }]], + ['debug', [{ a: 1, msg: 'foo' }]], + ['debug', [{ a: 9, b: 2, c: 3, msg: 'foo' }]], + ]) +}) + +test('a plain object argument is merged in, without a msg', () => { + const { logger, calls } = createTestSink() + + commonLoggerCreate(logger, { a: 1 }).debug({ structured: 'data' }) + + expect(calls[0]![1]).toStrictEqual([{ a: 1, structured: 'data' }]) +}) + +test('non-object arguments are joined into msg', () => { + const { logger, calls } = createTestSink() + const contextLogger = commonLoggerCreate(logger, { a: 1 }) + + contextLogger.warn('hello', { n: 1 }, 2) + contextLogger.log([1, 2]) + + expect(calls[0]![1]).toStrictEqual([{ a: 1, n: 1, msg: 'hello 2' }]) + expect(calls[1]![1]).toStrictEqual([{ a: 1, msg: '1,2' }]) +}) + +test('an argument wins over the context', () => { + const { logger, calls } = createTestSink() + + commonLoggerCreate(logger, { a: 1 }).log({ a: 9 }) + + expect(calls[0]![1]).toStrictEqual([{ a: 9 }]) +}) + +test('the first Error argument becomes err', () => { + const { logger, calls } = createTestSink() + const contextLogger = commonLoggerCreate(logger, { a: 1 }) + const err = new Error('boom') + + contextLogger.error(err) + contextLogger.error('failed', err) + contextLogger.error(err, new Error('second')) + + expect(calls[0]![1]).toStrictEqual([{ a: 1, err }]) + expect(calls[0]![1][0].err).toBe(err) + expect(calls[1]![1]).toStrictEqual([{ a: 1, err, msg: 'failed' }]) + expect(calls[2]![1]).toStrictEqual([{ a: 1, err, msg: 'Error: second' }]) + expect(calls[2]![1][0].err).toBe(err) +}) + +test('the context is copied on creation', () => { + const { logger, calls } = createTestSink() + const context: AnyObject = { a: 1 } + const contextLogger = commonLoggerCreate(logger, context) + + context['b'] = 2 + contextLogger.log('m') + + expect(calls[0]![1]).toStrictEqual([{ a: 1, msg: 'm' }]) +}) + +test('commonLoggerCreate with a context on console', () => { + const logger = commonLoggerCreate(console, { a: 1 }) + logger.debug('hey') + logger.log('hey') + logger.error('hey') +}) + +test('an empty context still wraps the arguments', () => { + const { logger, calls } = createTestSink() + + commonLoggerCreate(logger, {}).log('x') + + expect(calls[0]![1]).toStrictEqual([{ msg: 'x' }]) +}) + +function createTestSink(): { logger: CommonLogger; calls: [CommonLogLevel, any[]][] } { + const calls: [CommonLogLevel, any[]][] = [] + return { + logger: commonLoggerCreate((level, args) => calls.push([level, args])), + calls, + } +} diff --git a/packages/js-lib/src/log/commonLogger.ts b/packages/js-lib/src/log/commonLogger.ts index a07872558..40901c110 100644 --- a/packages/js-lib/src/log/commonLogger.ts +++ b/packages/js-lib/src/log/commonLogger.ts @@ -1,4 +1,5 @@ -import type { MutateOptions } from '../types.js' +import { _isPlainObject } from '../is.util.js' +import type { AnyObject, MutateOptions } from '../types.js' // copy-pasted to avoid weird circular dependency const _noop = (..._args: any[]): undefined => undefined @@ -125,14 +126,62 @@ export function commonLoggerPrefix(logger: CommonLogger, ...prefixes: any[]): Co } } +export type CommonLogSink = CommonLogger | CommonLogWithLevelFunction + +export interface CommonLoggerWithContext extends CommonLogger { + child: (context: AnyObject) => CommonLoggerWithContext +} + /** * Creates a CommonLogger from a single function that takes `level` and `args`. + * + * With a context, every call emits one object: plain-object args merged in, first Error as `err`, + * the rest joined into `msg`. */ -export function commonLoggerCreate(fn: CommonLogWithLevelFunction): CommonLogger { - return { - debug: (...args) => fn('debug', args), - log: (...args) => fn('log', args), - warn: (...args) => fn('warn', args), - error: (...args) => fn('error', args), +export function commonLoggerCreate(sink: CommonLogSink): CommonLogger +export function commonLoggerCreate(sink: CommonLogSink, context: AnyObject): CommonLoggerWithContext +export function commonLoggerCreate(sink: CommonLogSink, context?: AnyObject): CommonLogger { + const fn: CommonLogWithLevelFunction = + typeof sink === 'function' ? sink : (level, args) => sink[level](...args) + + if (!context) { + return { + debug: (...args) => fn('debug', args), + log: (...args) => fn('log', args), + warn: (...args) => fn('warn', args), + error: (...args) => fn('error', args), + } + } + + const ctx: AnyObject = { ...context } + + const logger: CommonLoggerWithContext = { + debug: (...args) => fn('debug', [toLogEntry(ctx, args)]), + log: (...args) => fn('log', [toLogEntry(ctx, args)]), + warn: (...args) => fn('warn', [toLogEntry(ctx, args)]), + error: (...args) => fn('error', [toLogEntry(ctx, args)]), + child: c => commonLoggerCreate(fn, { ...ctx, ...c }), + } + return logger +} + +function toLogEntry(context: AnyObject, args: any[]): AnyObject { + const entry: AnyObject = { ...context } + let err: Error | undefined + let msg: string | undefined + + for (const arg of args) { + if (_isPlainObject(arg)) { + Object.assign(entry, arg) + } else if (!err && arg instanceof Error) { + err = arg + } else { + const s = String(arg) + msg = msg === undefined ? s : `${msg} ${s}` + } } + + if (err) entry['err'] = err + if (msg !== undefined) entry['msg'] = msg + return entry } diff --git a/packages/js-lib/src/types.ts b/packages/js-lib/src/types.ts index fd9aa0f5e..2ec865693 100644 --- a/packages/js-lib/src/types.ts +++ b/packages/js-lib/src/types.ts @@ -30,6 +30,11 @@ export interface StringMap { */ export type AnyObject = Record +/** + * Object literal, with a prototype of `Object.prototype` or `null`. What `_isPlainObject` narrows to. + */ +export type PlainObject = Branded + export type AnyEnum = NumberEnum export type NumberEnum = Record export type StringEnum = Record