feat: commonLoggerCreate with a context, a pino-style child logger

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

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

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

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> = T extends NullishValue ? T : never
 type Truthy<T> = 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 ||

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