From 02327fc734bad5dbc7f647d0bdbc5d607d787801 Mon Sep 17 00:00:00 2001 From: Collin Duncan <3679940+cgduncan7@users.noreply.github.com> Date: Wed, 30 Nov 2022 11:56:39 +0100 Subject: [PATCH] Changing logger to work with AsyncLocalStorage to propagate logger to callee functions --- src/common/logger.ts | 33 ++--------- src/common/password.ts | 4 +- src/common/runner.ts | 16 +++--- src/common/scheduler.ts | 15 +++-- src/server/cron.ts | 30 ++++++---- src/server/http.ts | 95 ++++++++++++++++---------------- tests/unit/common/logger.test.ts | 23 +++----- 7 files changed, 95 insertions(+), 121 deletions(-) diff --git a/src/common/logger.ts b/src/common/logger.ts index 1509efa..22fb05f 100644 --- a/src/common/logger.ts +++ b/src/common/logger.ts @@ -1,39 +1,14 @@ +import { AsyncLocalStorage } from 'async_hooks' + export enum LogLevel { DEBUG, INFO, ERROR, } +export const asyncLocalStorage = new AsyncLocalStorage() + 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 diff --git a/src/common/password.ts b/src/common/password.ts index e918fa7..84b664e 100644 --- a/src/common/password.ts +++ b/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 } } diff --git a/src/common/runner.ts b/src/common/runner.ts index 7c03254..695b1fd 100644 --- a/src/common/runner.ts +++ b/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 { - 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 { - 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 { - 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 { - Logger.debug('Selecting opponent', opponent) + asyncLocalStorage.getStore()?.debug('Selecting opponent', opponent) const player2Search = await this.page?.waitForSelector( 'tr.res-make-player-2 > td > input' ) diff --git a/src/common/scheduler.ts b/src/common/scheduler.ts index 4c0413a..95ddf39 100644 --- a/src/common/scheduler.ts +++ b/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 export const schedule = async ( payload: SchedulerInput ): Promise => { - 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 }, diff --git a/src/server/cron.ts b/src/server/cron.ts index 11dd594..3884944 100644 --- a/src/server/cron.ts +++ b/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 }) - try { - await reserve() - Logger.info('Completed running cron job') - } catch (error: any) { - Logger.error('Error running cron job', { error: error.message }) - } + asyncLocalStorage.run(new Logger('cron', v4(), LogLevel.DEBUG), async () => { + const childLogger = asyncLocalStorage.getStore() + childLogger?.info('Running cron job', { timestamp }) + try { + await reserve() + childLogger?.info('Completed running cron job') + } catch (error: any) { + 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 }) } } diff --git a/src/server/http.ts b/src/server/http.ts index 5093dc5..dd2808b 100644 --- a/src/server/http.ts +++ b/src/server/http.ts @@ -1,58 +1,59 @@ 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) => { - 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') - res.writeHead(404, 'Not found') + await asyncLocalStorage.run(new Logger('request', v4(), LogLevel.DEBUG), async () => { + const logger = asyncLocalStorage.getStore() + logger?.debug('Incoming request') + const { url, method } = req + + if ( + !url || + !method || + !/^\/reservations$/.test(url) || + method.toLowerCase() !== 'post' + ) { + logger?.info('Not found') + res.writeHead(404, 'Not found') + res.end() + return + } + + let jsonBody: Record + const contentType = req.headers['content-type'] || 'application/json' + if (contentType !== 'application/json') { + logger?.error('Invalid content type', { contentType }) + res.writeHead(406, 'Unsupported content type') + res.end() + return + } + + try { + const length = Number.parseInt(req.headers['content-length'] || '0') + const encoding = req.readableEncoding || 'utf8' + jsonBody = await parseJson(length, encoding, req) + } catch (error: any) { + logger?.error('Failed to parse body', { error: error.message }) + res.writeHead(400, 'Bad request') + res.end() + return + } + + try { + await schedule(jsonBody) + } catch (error: any) { + logger?.error('Failed to schedule request', { error }) + res.writeHead(400, 'Bad request') + res.end() + return + } + res.end() - return - } - - let jsonBody: Record - const contentType = req.headers['content-type'] || 'application/json' - if (contentType !== 'application/json') { - Logger.error('Invalid content type', { contentType }) - res.writeHead(406, 'Unsupported content type') - res.end() - return - } - - try { - const length = Number.parseInt(req.headers['content-length'] || '0') - const encoding = req.readableEncoding || 'utf8' - jsonBody = await parseJson(length, encoding, req) - } catch (error: any) { - Logger.error('Failed to parse body', { error: error.message }) - res.writeHead(400, 'Bad request') - res.end() - return - } - - try { - await schedule(jsonBody) - } catch (error: any) { - Logger.error('Failed to schedule request', { error }) - res.writeHead(400, 'Bad request') - res.end() - return - } - - res.end() + }) }) export default server diff --git a/tests/unit/common/logger.test.ts b/tests/unit/common/logger.test.ts index cde3223..b5a3e24 100644 --- a/tests/unit/common/logger.test.ts +++ b/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) - Logger.debug('first') - Logger.info('second') - Logger.error('third', { errorMessage: 'test' }) + const logger = new Logger('tag', 'abc', LogLevel.DEBUG) + logger.debug('first') + logger.info('second') + 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) - Logger.debug("should't appear") + const logger = new Logger('tag', 'abc', LogLevel.INFO) + 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) - Logger.info('first', { password: 'test' }) + const logger = new Logger('tag', 'abc', LogLevel.DEBUG) + logger.info('first', { password: 'test' }) expect(consoleLogSpy).toHaveBeenCalledTimes(1) expect(consoleLogSpy).toHaveBeenNthCalledWith(