Changing logger to work with AsyncLocalStorage to propagate logger to callee functions

src/common/logger.ts

@@ -1,39 +1,14 @@
+import { AsyncLocalStorage } from 'async_hooks'
+
 export enum LogLevel {
   DEBUG,
   INFO,
   ERROR,
 }
 
+export const asyncLocalStorage = new AsyncLocalStorage<Logger>()
+
 export class Logger {
-  private static instance: LoggerInstance
-
-  public static instantiate(
-    tag: string,
-    correlationId: string,
-    level = LogLevel.ERROR
-  ): LoggerInstance {
-    Logger.instance = new LoggerInstance(tag, correlationId, level)
-    return Logger.instance
-  }
-
-  public static getInstance(): LoggerInstance {
-    return Logger.instance
-  }
-
-  public static debug(message: string, details?: unknown): void {
-    Logger.getInstance().debug(message, details)
-  }
-
-  public static info(message: string, details?: unknown): void {
-    Logger.getInstance().info(message, details)
-  }
-
-  public static error(message: string, details?: unknown): void {
-    Logger.getInstance().error(message, details)
-  }
-}
-
-export class LoggerInstance {
   private readonly tag: string
   private readonly correlationId: string
   private readonly level: LogLevel

src/common/password.ts

@@ -1,6 +1,6 @@
 import argon2 from 'argon2'
 import crypto from 'crypto'
-import { Logger } from './logger'
+import { asyncLocalStorage } from './logger'
 
 const SALT_LENGTH = Number.parseInt(process.env.SALT_LENGTH || '32', 10)
 
@@ -42,7 +42,7 @@ export const hashPassword = async (password: string) => {
     const hash = await generateHash(password, saltBuffer)
     return hash
   } catch (err: any) {
-    Logger.error('Error hashing and salting password', { message: err.message })
+    asyncLocalStorage.getStore()?.error('Error hashing and salting password', { message: err.message })
     throw err
   }
 }

src/common/runner.ts

@@ -7,7 +7,7 @@ import puppeteer, {
   LaunchOptions,
   Page,
 } from 'puppeteer'
-import { Logger } from './logger'
+import { asyncLocalStorage } from './logger'
 import { Opponent, Reservation } from './reservation'
 
 export class Runner {
@@ -26,7 +26,7 @@ export class Runner {
   }
 
   public async run(reservation: Reservation): Promise<boolean> {
-    Logger.debug('Launching browser')
+    asyncLocalStorage.getStore()?.debug('Launching browser')
     if (!this.browser) {
       this.browser = await puppeteer.launch(this.options)
     }
@@ -36,7 +36,7 @@ export class Runner {
   }
 
   private async login(username: string, password: string) {
-    Logger.debug('Logging in')
+    asyncLocalStorage.getStore()?.debug('Logging in')
     await this.page?.goto('https://squashcity.baanreserveren.nl/')
     await this.page
       ?.waitForSelector('input[name=username]')
@@ -54,7 +54,7 @@ export class Runner {
       reservation.booked = true
       return true
     } catch (err) {
-      Logger.error('Error making reservation', reservation.format())
+      asyncLocalStorage.getStore()?.error('Error making reservation', reservation.format())
       return false
     }
   }
@@ -74,10 +74,10 @@ export class Runner {
   }
 
   private async navigateToDay(date: Dayjs): Promise<void> {
-    Logger.debug(`Navigating to ${date.format()}`)
+    asyncLocalStorage.getStore()?.debug(`Navigating to ${date.format()}`)
 
     if (this.getLastVisibleDay().isBefore(date)) {
-      Logger.debug('Date is on different page, increase month')
+      asyncLocalStorage.getStore()?.debug('Date is on different page, increase month')
       await this.page?.waitForSelector('td.month.next').then((d) => d?.click())
     }
 
@@ -96,7 +96,7 @@ export class Runner {
   }
 
   private async selectAvailableTime(res: Reservation): Promise<void> {
-    Logger.debug('Selecting available time', res.format())
+    asyncLocalStorage.getStore()?.debug('Selecting available time', res.format())
     let freeCourt: ElementHandle | null | undefined
     let i = 0
     while (i < res.possibleDates.length && !freeCourt) {
@@ -116,7 +116,7 @@ export class Runner {
   }
 
   private async selectOpponent(opponent: Opponent): Promise<void> {
-    Logger.debug('Selecting opponent', opponent)
+    asyncLocalStorage.getStore()?.debug('Selecting opponent', opponent)
     const player2Search = await this.page?.waitForSelector(
       'tr.res-make-player-2 > td > input'
     )

src/common/scheduler.ts

@@ -1,7 +1,6 @@
 import { Dayjs } from 'dayjs'
-import { v4 } from 'uuid'
 
-import { Logger, LogLevel } from './logger'
+import { asyncLocalStorage } from './logger'
 import { Reservation } from './reservation'
 import { validateJSONRequest } from './request'
 import { reserve } from './reserver'
@@ -20,23 +19,23 @@ export type SchedulerInput = Record<string, unknown>
 export const schedule = async (
   payload: SchedulerInput
 ): Promise<SchedulerResult> => {
-  Logger.instantiate('scheduler', v4(), LogLevel.DEBUG)
+  const logger = asyncLocalStorage.getStore()
 
-  Logger.debug('Handling reservation', { payload })
+  logger?.debug('Handling reservation', { payload })
   let reservation: Reservation
   try {
     reservation = await validateJSONRequest(payload)
   } catch (err) {
-    Logger.error('Failed to validate request', { err })
+    logger?.error('Failed to validate request', { err })
     throw err
   }
 
-  Logger.debug('Successfully validated request', {
+  logger?.debug('Successfully validated request', {
     reservation: reservation.format(),
   })
 
   if (!reservation.isAvailableForReservation()) {
-    Logger.debug(
+    logger?.debug(
       'Reservation date is more than 7 days away; saving for later reservation'
     )
 
@@ -50,7 +49,7 @@ export const schedule = async (
     }
   }
 
-  Logger.info('Reservation request can be performed now')
+  logger?.info('Reservation request can be performed now')
   await reserve(reservation)
   return {
     scheduledReservation: { reservation },

src/server/cron.ts

@@ -1,5 +1,6 @@
 import { schedule, ScheduledTask, ScheduleOptions } from 'node-cron'
-import { Logger } from '../common/logger'
+import { v4 } from 'uuid'
+import { asyncLocalStorage, Logger, LogLevel } from '../common/logger'
 import { reserve } from '../common/reserver'
 
 const tasks: ScheduledTask[] = []
@@ -10,33 +11,38 @@ const getTaskConfig = (name: string): ScheduleOptions => ({
   timezone: 'Europe/Amsterdam',
 })
 
+const logger = new Logger('cron', 'default', LogLevel.DEBUG)
+
 export const startTasks = () => {
   try {
     const task = schedule(
       '0 * * * * *',
       async (timestamp) => {
-        Logger.info('Running cron job', { timestamp })
+        asyncLocalStorage.run(new Logger('cron', v4(), LogLevel.DEBUG), async () => {
+          const childLogger = asyncLocalStorage.getStore()
+          childLogger?.info('Running cron job', { timestamp })
           try {
             await reserve()
-          Logger.info('Completed running cron job')
+            childLogger?.info('Completed running cron job')
           } catch (error: any) {
-          Logger.error('Error running cron job', { error: error.message })
+            childLogger?.error('Error running cron job', { error: error.message })
           }
+        })
       },
       getTaskConfig('reserver cron')
     )
-    Logger.debug('Started cron task')
+    logger.debug('Started cron task')
     tasks.push(task)
   } catch (error: any) {
-    Logger.error('Failed to start tasks', { error: error.message })
+    logger.error('Failed to start tasks', { error: error.message })
   }
 }
 
 export const stopTasks = () => {
   try {
     tasks.map((task) => task.stop())
-    Logger.debug('Stopped cron tasks')
+    logger.debug('Stopped cron tasks')
   } catch (error: any) {
-    Logger.error('Failed to stop tasks', { error: error.message })
+    logger.error('Failed to stop tasks', { error: error.message })
   }
 }

src/server/http.ts

@@ -1,23 +1,23 @@
 import http from 'http'
 import { v4 } from 'uuid'
-import { Logger, LogLevel } from '../common/logger'
+import { asyncLocalStorage, Logger, LogLevel } from '../common/logger'
 import { schedule } from '../common/scheduler'
 import { parseJson } from './utils'
 
 // Handles POST requests to /reservations
 const server = http.createServer(async (req, res) => {
+  await asyncLocalStorage.run(new Logger('request', v4(), LogLevel.DEBUG), async () => {
+    const logger = asyncLocalStorage.getStore()
+    logger?.debug('Incoming request')
     const { url, method } = req
   
-  Logger.instantiate('request', v4(), LogLevel.DEBUG)
-  Logger.debug('Incoming request')
-
     if (
       !url ||
       !method ||
       !/^\/reservations$/.test(url) ||
       method.toLowerCase() !== 'post'
     ) {
-    Logger.info('Not found')
+      logger?.info('Not found')
       res.writeHead(404, 'Not found')
       res.end()
       return
@@ -26,7 +26,7 @@ const server = http.createServer(async (req, res) => {
     let jsonBody: Record<string, unknown>
     const contentType = req.headers['content-type'] || 'application/json'
     if (contentType !== 'application/json') {
-    Logger.error('Invalid content type', { contentType })
+      logger?.error('Invalid content type', { contentType })
       res.writeHead(406, 'Unsupported content type')
       res.end()
       return
@@ -37,7 +37,7 @@ const server = http.createServer(async (req, res) => {
       const encoding = req.readableEncoding || 'utf8'
       jsonBody = await parseJson(length, encoding, req)
     } catch (error: any) {
-    Logger.error('Failed to parse body', { error: error.message })
+      logger?.error('Failed to parse body', { error: error.message })
       res.writeHead(400, 'Bad request')
       res.end()
       return
@@ -46,7 +46,7 @@ const server = http.createServer(async (req, res) => {
     try {
       await schedule(jsonBody)
     } catch (error: any) {
-    Logger.error('Failed to schedule request', { error })
+      logger?.error('Failed to schedule request', { error })
       res.writeHead(400, 'Bad request')
       res.end()
       return
@@ -54,5 +54,6 @@ const server = http.createServer(async (req, res) => {
   
     res.end()
   })
+})
 
 export default server

tests/unit/common/logger.test.ts

@@ -5,23 +5,16 @@ describe('Logger', () => {
     jest.resetAllMocks()
   })
 
-  test('should create a single instance of LoggerInstance', () => {
-    const a = Logger.instantiate('tag', 'abc', LogLevel.DEBUG)
-    const b = Logger.getInstance()
-
-    expect(a).toStrictEqual(b)
-  })
-
   test('should log messages', () => {
     const consoleLogSpy = jest.fn()
     const consoleErrorSpy = jest.fn()
     jest.spyOn(console, 'log').mockImplementation(consoleLogSpy)
     jest.spyOn(console, 'error').mockImplementation(consoleErrorSpy)
 
-    Logger.instantiate('tag', 'abc', LogLevel.DEBUG)
+    const logger = new Logger('tag', 'abc', LogLevel.DEBUG)
-    Logger.debug('first')
+    logger.debug('first')
-    Logger.info('second')
+    logger.info('second')
-    Logger.error('third', { errorMessage: 'test' })
+    logger.error('third', { errorMessage: 'test' })
 
     expect(consoleLogSpy).toHaveBeenCalledTimes(2)
     expect(consoleLogSpy).toHaveBeenNthCalledWith(
@@ -55,8 +48,8 @@ describe('Logger', () => {
     const consoleLogSpy = jest.fn()
     jest.spyOn(console, 'log').mockImplementationOnce(consoleLogSpy)
 
-    Logger.instantiate('tag', 'abc', LogLevel.INFO)
+    const logger = new Logger('tag', 'abc', LogLevel.INFO)
-    Logger.debug("should't appear")
+    logger.debug("shouldn't appear")
 
     expect(consoleLogSpy).not.toHaveBeenCalled()
   })
@@ -67,8 +60,8 @@ describe('Logger', () => {
     jest.spyOn(console, 'log').mockImplementation(consoleLogSpy)
     jest.spyOn(console, 'error').mockImplementation(consoleErrorSpy)
 
-    Logger.instantiate('tag', 'abc', LogLevel.DEBUG)
+    const logger = new Logger('tag', 'abc', LogLevel.DEBUG)
-    Logger.info('first', { password: 'test' })
+    logger.info('first', { password: 'test' })
 
     expect(consoleLogSpy).toHaveBeenCalledTimes(1)
     expect(consoleLogSpy).toHaveBeenNthCalledWith(