Improvements to Logging (#525)

* refactor: 💡 allow more control of logger config

* feat: 🎸 add timing middleware to calculate response time

* chore: 🤖 changeset

* chore: 🤖 lint

.changeset/famous-adults-sniff.md

@@ -0,0 +1,5 @@
+---
+"@sebspark/logging": minor
+---
+
+Added timing middleware and improved logger configuration

packages/logging/src/lib/logger.ts

@@ -14,7 +14,6 @@ import {
   format,
 } from 'winston'
 import type * as Transport from 'winston-transport'
-import { getCorrId } from './correlationid'
 
 let loggers: Record<string, Logger> = {}
 
@@ -51,14 +50,15 @@ export type LogOptions = {
   level?: LogLevel
   showLogs?: boolean
   shouldSendToGcp?: boolean
+  enableConsole?: boolean
   gcpProjectId?: string
   formattingOptions?: {
     colorize?: boolean
     timestamp?: boolean
     align?: boolean
-    corrId?: boolean
     stack?: boolean
   }
+  defaultMeta?: Record<string, unknown>
   logHttpFunc?: LogFunc
   logHttpErrorFunc?: LogErrorFunc
 }
@@ -75,15 +75,16 @@ export const getLogger = ({
   level = 'info',
   showLogs = false, // force show logs on test environments
   shouldSendToGcp = false,
+  enableConsole = true,
   gcpProjectId,
   formattingOptions = {},
+  defaultMeta = {},
   logHttpFunc = logHttp,
   logHttpErrorFunc = logHttpError,
 }: LogOptions): LoggerResult => {
   const defaultFormattingOptions = {
     colorize: true,
     timestamp: true,
-    corrId: false,
     align: true,
     stack: true,
   }
@@ -101,15 +102,7 @@ export const getLogger = ({
       consoleFormattingOptions.timestamp ? format.timestamp() : format.simple(),
       consoleFormattingOptions.align ? format.align() : format.simple(),
       format.printf((info) => {
-        let output = `[${info.timestamp}]`
-        if (consoleFormattingOptions.corrId) {
-          const corrId = getCorrId()
-          if (corrId) {
-            output += ` [${corrId}]`
-          }
-        }
-        output += ` ${info.level}: ${info.message}`
-        return output
+        return `[${info.timestamp}] ${info.level}: ${info.message}`
       }),
       consoleFormattingOptions.stack
         ? format.errors({ stack: true })
@@ -128,24 +121,25 @@ export const getLogger = ({
       loggingWinstonSettings.projectId = gcpProjectId
     }
 
-    const transports: Transport[] = shouldSendToGcp
-      ? [
-          new WinstonTransports.Console({
-            format: winstonConsoleFormat,
-          }),
-          new LoggingWinston(loggingWinstonSettings),
-        ]
-      : [
-          new WinstonTransports.Console({
-            format: winstonConsoleFormat,
-          }),
-        ]
+    const transports: Transport[] = []
+
+    if (enableConsole) {
+      transports.push(
+        new WinstonTransports.Console({
+          format: winstonConsoleFormat,
+        })
+      )
+    }
+    if (shouldSendToGcp) {
+      transports.push(new LoggingWinston(loggingWinstonSettings))
+    }
 
     const silent = showLogs ? false : isSilent
     loggers[service] = createLogger({
       level,
       transports,
       silent,
+      defaultMeta,
     })
   }
   return {

packages/logging/src/lib/timing.spec.ts

@@ -0,0 +1,50 @@
+import type { Response } from 'express'
+import type { Request } from 'express'
+import type { ParamsDictionary } from 'express-serve-static-core'
+import type { NextFunction } from 'express-serve-static-core'
+import type { ParsedQs } from 'qs'
+import { expect, test, vi } from 'vitest'
+import {
+  asyncLocalStorage,
+  getElapsedTime,
+  getStartTime,
+  runWithTiming,
+  timingMiddleware,
+} from './timing'
+
+test('getStartTime returns the start time', () => {
+  asyncLocalStorage.run({ startTime: 12345 }, () => {
+    expect(getStartTime()).toBe(12345)
+  })
+})
+
+test('getElapsedTime returns the elapsed time', () => {
+  asyncLocalStorage.run({ startTime: Date.now() - 1000 }, () => {
+    expect(getElapsedTime()).toBeGreaterThanOrEqual(1000)
+  })
+})
+
+test('getElapsedTime returns 0 if no start time', () => {
+  expect(getElapsedTime()).toBe(0)
+})
+
+test('timingMiddleware sets X-Start-Time header', async () => {
+  const req = {} as Request<
+    ParamsDictionary,
+    unknown,
+    unknown,
+    ParsedQs,
+    Record<string, unknown>
+  >
+  const res = {
+    setHeader: vi.fn(),
+  } as unknown as Response<unknown, Record<string, unknown>>
+  const next = vi.fn() as unknown as NextFunction
+
+  await runWithTiming(async () => {
+    timingMiddleware(req, res, next)
+  })
+
+  expect(res.setHeader).toHaveBeenCalledWith('X-Start-Time', expect.any(String))
+  expect(next).toHaveBeenCalled()
+})

packages/logging/src/lib/timing.ts

@@ -0,0 +1,41 @@
+import { AsyncLocalStorage } from 'node:async_hooks'
+import type { NextFunction, Request, Response } from 'express'
+
+export const asyncLocalStorage = new AsyncLocalStorage<{ startTime: number }>()
+
+export const runWithTiming = async (callback: () => Promise<void>) => {
+  return new Promise<void>((res) => {
+    const startTime = Date.now()
+    asyncLocalStorage.run({ startTime }, async () => {
+      await callback()
+      res()
+    })
+  })
+}
+
+export const getStartTime = () => {
+  return asyncLocalStorage.getStore()?.startTime
+}
+
+export const getElapsedTime = () => {
+  const startTime = getStartTime()
+  if (!startTime) {
+    return 0
+  }
+
+  return Date.now() - startTime
+}
+
+export const timingMiddleware = (
+  _req: Request,
+  res: Response,
+  next: NextFunction
+) => {
+  runWithTiming(async () => {
+    const startTime = getStartTime()
+    if (startTime) {
+      res.setHeader('X-Start-Time', startTime.toString())
+    }
+    next()
+  })
+}