From c42d5f5a9c34b2cfef407dbc79ec5c2a41c9d60d Mon Sep 17 00:00:00 2001 From: Zachary Rogers Date: Wed, 28 Aug 2024 21:19:33 -0700 Subject: [PATCH 1/4] devex: Make a unified logger that all web-api can pull from rather than going through applicationContext. --- web-api/src/app-public.ts | 4 +- web-api/src/app.ts | 4 +- web-api/src/applicationContext.ts | 23 ++--- web-api/src/createLogger.ts | 14 ++- web-api/src/genericHandler.ts | 4 +- .../cognitoAuthorizer/createAuthorizer.ts | 34 +++---- .../lambdas/migration/migration-segments.ts | 25 +++-- web-api/src/lambdas/migration/migration.ts | 25 +++-- web-api/src/logger.test.ts | 6 +- web-api/src/logger.ts | 98 +++++++++---------- web-api/src/utilities/logger/getLogger.ts | 36 +++++++ 11 files changed, 139 insertions(+), 134 deletions(-) create mode 100644 web-api/src/utilities/logger/getLogger.ts diff --git a/web-api/src/app-public.ts b/web-api/src/app-public.ts index 07567744d37..ee9a13732a0 100644 --- a/web-api/src/app-public.ts +++ b/web-api/src/app-public.ts @@ -1,9 +1,9 @@ import { createApplicationContext } from './applicationContext'; +import { expressLogger } from './logger'; import { get } from './persistence/dynamodbClientService'; import { getCurrentInvoke } from '@vendia/serverless-express'; import { json, urlencoded } from 'body-parser'; import { lambdaWrapper } from './lambdaWrapper'; -import { logger } from './logger'; import { set } from 'lodash'; import cors from 'cors'; import express from 'express'; @@ -67,7 +67,7 @@ app.use((req, res, next) => { next(); }); -app.use(logger()); +app.use(expressLogger); import { advancedQueryLimiter } from './middleware/advancedQueryLimiter'; import { casePublicSearchLambda } from './lambdas/public-api/casePublicSearchLambda'; diff --git a/web-api/src/app.ts b/web-api/src/app.ts index 81687c34410..61374611438 100644 --- a/web-api/src/app.ts +++ b/web-api/src/app.ts @@ -50,6 +50,7 @@ import { downloadPolicyUrlLambda } from './lambdas/documents/downloadPolicyUrlLa import { editPaperFilingLambda } from './lambdas/documents/editPaperFilingLambda'; import { editPractitionerDocumentLambda } from './lambdas/practitioners/editPractitionerDocumentLambda'; import { exportPendingReportLambda } from '@web-api/lambdas/pendingItems/exportPendingReportLambda'; +import { expressLogger } from './logger'; import { fetchPendingItemsLambda } from './lambdas/pendingItems/fetchPendingItemsLambda'; import { fileAndServeCourtIssuedDocumentLambda } from './lambdas/cases/fileAndServeCourtIssuedDocumentLambda'; import { fileCorrespondenceDocumentLambda } from './lambdas/correspondence/fileCorrespondenceDocumentLambda'; @@ -127,7 +128,6 @@ import { getUsersPendingEmailLambda } from './lambdas/users/getUsersPendingEmail import { getWorkItemLambda } from './lambdas/workitems/getWorkItemLambda'; import { ipLimiter } from './middleware/ipLimiter'; import { lambdaWrapper } from './lambdaWrapper'; -import { logger } from './logger'; import { loginLambda } from '@web-api/lambdas/auth/loginLambda'; import { opinionAdvancedSearchLambda } from './lambdas/documents/opinionAdvancedSearchLambda'; import { orderAdvancedSearchLambda } from './lambdas/documents/orderAdvancedSearchLambda'; @@ -276,7 +276,7 @@ app.use((req, res, next) => { next(); }); -app.use(logger()); +app.use(expressLogger); /** * Important note: order of routes DOES matter! diff --git a/web-api/src/applicationContext.ts b/web-api/src/applicationContext.ts index 92b9a3d4ef1..2129a441503 100644 --- a/web-api/src/applicationContext.ts +++ b/web-api/src/applicationContext.ts @@ -34,7 +34,6 @@ import { UserCase } from '../../shared/src/business/entities/UserCase'; import { UserCaseNote } from '../../shared/src/business/entities/notes/UserCaseNote'; import { WorkItem } from '../../shared/src/business/entities/WorkItem'; import { WorkerMessage } from '@web-api/gateways/worker/workerRouter'; -import { createLogger } from './createLogger'; import { defaultProvider } from '@aws-sdk/credential-provider-node'; import { environment } from '@web-api/environment'; import { @@ -50,6 +49,7 @@ import { getDocumentGenerators } from './getDocumentGenerators'; import { getDynamoClient } from '@web-api/persistence/dynamo/getDynamoClient'; import { getEmailClient } from './persistence/messages/getEmailClient'; import { getEnvironment, getUniqueId } from '../../shared/src/sharedAppContext'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { getNotificationClient } from '@web-api/notifications/getNotificationClient'; import { getNotificationService } from '@web-api/notifications/getNotificationService'; import { getPersistenceGateway } from './getPersistenceGateway'; @@ -72,7 +72,6 @@ import { sendSetTrialSessionCalendarEvent } from './persistence/messages/sendSet import { sendSlackNotification } from './dispatchers/slack/sendSlackNotification'; import { worker } from '@web-api/gateways/worker/worker'; import { workerLocal } from '@web-api/gateways/worker/workerLocal'; - import axios from 'axios'; import pug from 'pug'; import sass from 'sass'; @@ -97,18 +96,13 @@ const entitiesByName = { WorkItem, }; -export const createApplicationContext = ( - appContextUser = {}, - logger = createLogger(), -) => { +export const createApplicationContext = (appContextUser = {}) => { const user = new User(appContextUser); - + const logger = getLogger(); if (process.env.NODE_ENV === 'production') { const authenticated = user && Object.keys(user).length; - logger.defaultMeta = logger.defaultMeta || {}; - logger.defaultMeta.user = authenticated - ? user - : { role: 'unauthenticated' }; + const userForLogging = authenticated ? user : { role: 'unauthenticated' }; + logger.addContext({ user: userForLogging }); } return { @@ -282,12 +276,7 @@ export const createApplicationContext = ( }), isAuthorized, isCurrentColorActive, - logger: { - debug: (message, context?) => logger.debug(message, { context }), - error: (message, context?) => logger.error(message, { context }), - info: (message, context?) => logger.info(message, { context }), - warn: (message, context?) => logger.warn(message, { context }), - }, + logger, setTimeout: (callback, timeout) => setTimeout(callback, timeout), }; }; diff --git a/web-api/src/createLogger.ts b/web-api/src/createLogger.ts index 45013555f18..d62c42c0284 100644 --- a/web-api/src/createLogger.ts +++ b/web-api/src/createLogger.ts @@ -1,10 +1,11 @@ -import { cloneDeep, isEqual, unset } from 'lodash'; import { + LoggerOptions, config, createLogger as createWinstonLogger, format, transports, } from 'winston'; +import { cloneDeep, isEqual, unset } from 'lodash'; import colorize from 'logform/colorize'; import combine from 'logform/combine'; import errors from 'logform/errors'; @@ -37,12 +38,17 @@ export const removeDuplicateLogInformation = format(logEntry => { return copy; }); -export const createLogger = (opts = {}) => { +export const createLogger = (opts: LoggerOptions = {}) => { const options = { defaultMeta: {}, - level: opts.logLevel || process.env.LOG_LEVEL || 'debug', + level: opts.level || process.env.LOG_LEVEL || 'debug', levels: config.syslog.levels, - transports: [new transports.Console()], + transports: [ + new transports.Console({ + handleExceptions: true, + handleRejections: true, + }), + ], ...opts, }; diff --git a/web-api/src/genericHandler.ts b/web-api/src/genericHandler.ts index 0ee582fc501..920c1763704 100644 --- a/web-api/src/genericHandler.ts +++ b/web-api/src/genericHandler.ts @@ -85,7 +85,9 @@ export const genericHandler = ( return handle(awsEvent, async () => { const user = getUserFromAuthHeader(awsEvent); const clientConnectionId = getConnectionIdFromEvent(awsEvent); - const applicationContext = createApplicationContext(user, awsEvent.logger); + // pinkLog('I am the event logger', awsEvent.logger); + console.log('I am awsEvent: ', awsEvent); + const applicationContext = createApplicationContext(user); delete awsEvent.logger; diff --git a/web-api/src/lambdas/cognitoAuthorizer/createAuthorizer.ts b/web-api/src/lambdas/cognitoAuthorizer/createAuthorizer.ts index 1a0ca6c3d5c..aa54c27ff96 100644 --- a/web-api/src/lambdas/cognitoAuthorizer/createAuthorizer.ts +++ b/web-api/src/lambdas/cognitoAuthorizer/createAuthorizer.ts @@ -2,36 +2,15 @@ import { APIGatewayAuthorizerResult, APIGatewayRequestAuthorizerEvent, } from 'aws-lambda'; -import { createLogger } from '../../createLogger'; import { createPublicKey } from 'crypto'; import { environment } from '@web-api/environment'; -import { transports } from 'winston'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import axios from 'axios'; import jwk from 'jsonwebtoken'; -const transport = new transports.Console({ - handleExceptions: true, - handleRejections: true, -}); - const issMain = `https://cognito-idp.us-east-1.amazonaws.com/${environment.userPoolId}`; const issIrs = `https://cognito-idp.us-east-1.amazonaws.com/${environment.userPoolIrsId}`; -const getLogger = context => { - return createLogger({ - defaultMeta: { - environment: { - stage: process.env.STAGE, - }, - requestId: { - authorizer: context.awsRequestId, - }, - }, - logLevel: context.logLevel, - transports: [transport], - }); -}; - const decodeToken = requestToken => { const { header, payload } = jwk.decode(requestToken, { complete: true }); return { iss: payload.iss, kid: header.kid }; @@ -74,7 +53,16 @@ const throw401GatewayError = () => { export const createAuthorizer = getToken => async (event: APIGatewayRequestAuthorizerEvent, context) => { - const logger = getLogger(context); + const logger = getLogger(); + logger.clearContext(); + logger.addContext({ + environment: { + stage: process.env.STAGE, + }, + requestId: { + authorizer: context.awsRequestId, + }, + }); let token; try { diff --git a/web-api/src/lambdas/migration/migration-segments.ts b/web-api/src/lambdas/migration/migration-segments.ts index e994107ad90..1060aa2a2ac 100644 --- a/web-api/src/lambdas/migration/migration-segments.ts +++ b/web-api/src/lambdas/migration/migration-segments.ts @@ -11,7 +11,7 @@ import { createISODateString, dateStringsCompared, } from '@shared/business/utilities/DateHandler'; -import { createLogger } from '@web-api/createLogger'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { migrationsToRun } from './migrationsToRun'; import { migrateItems as validationMigration } from './migrations/0000-validate-all-items'; import promiseRetry from 'promise-retry'; @@ -150,19 +150,16 @@ export const processItems = async ( }; export const handler: Handler = async (event: SQSEvent, context: Context) => { - const applicationContext = createApplicationContext( - {}, - createLogger({ - defaultMeta: { - environment: { - stage: process.env.STAGE || 'local', - }, - requestId: { - lambda: context.awsRequestId, - }, - }, - }), - ); + const applicationContext = createApplicationContext({}); + getLogger().clearContext(); + getLogger().addContext({ + environment: { + stage: process.env.STAGE || 'local', + }, + requestId: { + lambda: context.awsRequestId, + }, + }); const { Records } = event; const { body, receiptHandle } = Records[0]; const { segment, totalSegments } = JSON.parse(body); diff --git a/web-api/src/lambdas/migration/migration.ts b/web-api/src/lambdas/migration/migration.ts index f39750f56aa..d94a47a1a5e 100644 --- a/web-api/src/lambdas/migration/migration.ts +++ b/web-api/src/lambdas/migration/migration.ts @@ -5,7 +5,7 @@ import { } from '@aws-sdk/lib-dynamodb'; import { DynamoDBClient } from '@aws-sdk/client-dynamodb'; import { createApplicationContext } from '@web-api/applicationContext'; -import { createLogger } from '@web-api/createLogger'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { migrateRecords as migrations } from './migration-segments'; import { unmarshall } from '@aws-sdk/util-dynamodb'; import type { DynamoDBStreamEvent, Handler } from 'aws-lambda'; @@ -61,19 +61,16 @@ export const handler: Handler = async (event: DynamoDBStreamEvent, context) => { marshallOptions: { removeUndefinedValues: true }, }); - const applicationContext = createApplicationContext( - {}, - createLogger({ - defaultMeta: { - environment: { - stage: process.env.STAGE || 'local', - }, - requestId: { - lambda: context.awsRequestId, - }, - }, - }), - ); + const applicationContext = createApplicationContext({}); + getLogger().clearContext(); + getLogger().addContext({ + environment: { + stage: process.env.STAGE || 'local', + }, + requestId: { + lambda: context.awsRequestId, + }, + }); const { Records } = event; diff --git a/web-api/src/logger.test.ts b/web-api/src/logger.test.ts index 4cc418801aa..d8f1dfe8a34 100644 --- a/web-api/src/logger.test.ts +++ b/web-api/src/logger.test.ts @@ -1,4 +1,4 @@ -import { logger } from './logger'; +import { expressLogger } from './logger'; import { transports } from 'winston'; import fs from 'fs'; jest.mock('@vendia/serverless-express'); @@ -36,7 +36,7 @@ describe('logger', () => { const subject = (request, response) => new Promise(resolve => { - const middleware = logger( + const middleware = expressLogger( new transports.Stream({ stream: fs.createWriteStream('/dev/null'), }), @@ -51,7 +51,7 @@ describe('logger', () => { }); it('defaults to using a console logger if not specified', () => { - const middleware = logger(); + const middleware = expressLogger(); jest.spyOn(console, 'log').mockImplementation(jest.fn()); middleware(req, res, () => { diff --git a/web-api/src/logger.ts b/web-api/src/logger.ts index 89261ab47cc..2bc1e530acd 100644 --- a/web-api/src/logger.ts +++ b/web-api/src/logger.ts @@ -1,69 +1,59 @@ /* eslint-disable @miovision/disallow-date/no-new-date */ import { cloneDeep, get } from 'lodash'; -import { createLogger } from './createLogger'; import { getCurrentInvoke } from '@vendia/serverless-express'; -import { transports } from 'winston'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; -let cache; -const console = () => - cache || - (cache = new transports.Console({ - handleExceptions: true, - handleRejections: true, - })); +export const expressLogger = (req, res, next) => { + const logger = getLogger(); + if (process.env.NODE_ENV === 'production') { + const requestBody = cloneDeep(req.body); -export const logger = (transport = console()) => { - const createdLogger = createLogger({ transports: [transport] }); - return (req, res, next) => { - if (process.env.NODE_ENV === 'production') { - const requestBody = cloneDeep(req.body); - - if (requestBody) { - redactPasswordFields(requestBody); - } - const currentInvoke = getCurrentInvoke(); - createdLogger.defaultMeta = { - environment: { - color: process.env.CURRENT_COLOR || 'green', - stage: process.env.STAGE || 'local', - }, - request: { - body: JSON.stringify(requestBody), - headers: req.headers, - method: req.method, - url: req.url, - }, - requestId: { - apiGateway: get(currentInvoke, 'event.requestContext.requestId'), - applicationLoadBalancer: req.get('x-amzn-trace-id'), - lambda: get(currentInvoke, 'context.awsRequestId'), - }, - }; + if (requestBody) { + redactPasswordFields(requestBody); } + const currentInvoke = getCurrentInvoke(); + logger.addContext({ + environment: { + color: process.env.CURRENT_COLOR || 'green', + stage: process.env.STAGE || 'local', + }, + request: { + body: JSON.stringify(requestBody), + headers: req.headers, + method: req.method, + url: req.url, + }, + requestId: { + apiGateway: get(currentInvoke, 'event.requestContext.requestId'), + applicationLoadBalancer: req.get('x-amzn-trace-id'), + lambda: get(currentInvoke, 'context.awsRequestId'), + }, + }); + } - createdLogger.debug(`Request started: ${req.method} ${req.url}`); - - req.locals = req.locals || {}; - req.locals.logger = createdLogger; - req.locals.startTime = new Date(); + logger.debug(`Request started: ${req.method} ${req.url}`); - const { end } = res; + req.locals = req.locals || {}; + req.locals.logger = logger; + req.locals.startTime = new Date(); - res.end = function () { - end.apply(this, arguments); - const responseTimeMs = new Date() - req.locals.startTime; + const { end } = res; - req.locals.logger.info(`Request ended: ${req.method} ${req.url}`, { - response: { - responseSize: parseInt(res.get('content-length') ?? '0'), - responseTimeMs, - statusCode: res.statusCode, - }, - }); - }; + res.end = function () { + end.apply(this, arguments); + const responseTimeMs = new Date() - req.locals.startTime; - return next(); + logger.info(`Request ended: ${req.method} ${req.url}`, { + response: { + responseSize: parseInt(res.get('content-length') ?? '0'), + responseTimeMs, + statusCode: res.statusCode, + }, + }); + logger.clearContext(); }; + + return next(); }; function redactPasswordFields(obj) { diff --git a/web-api/src/utilities/logger/getLogger.ts b/web-api/src/utilities/logger/getLogger.ts new file mode 100644 index 00000000000..13bef67b4e2 --- /dev/null +++ b/web-api/src/utilities/logger/getLogger.ts @@ -0,0 +1,36 @@ +import { Logger } from 'winston'; +import { createLogger } from '@web-api/createLogger'; + +let loggerCache: LoggerType; + +export const getLogger = (): LoggerType => { + if (!loggerCache) { + const logger = createLogger(); + loggerCache = { + addContext: (newMeta: Record) => { + logger.defaultMeta = { + ...logger.defaultMeta, + ...newMeta, + }; + }, + clearContext: () => { + logger.defaultMeta = undefined; + }, + debug: (message, context?) => logger.debug(message, { context }), + error: (message, context?) => logger.error(message, { context }), + info: (message, context?) => logger.info(message, { context }), + warn: (message, context?) => logger.warn(message, { context }), + }; + } + + return loggerCache; +}; + +type LoggerType = { + debug: (message: any, context?: any) => Logger; + error: (message: any, context?: any) => Logger; + info: (message: any, context?: any) => Logger; + warn: (message: any, context?: any) => Logger; + clearContext: () => void; + addContext: (newMeta: Record) => void; +}; From 1e91142aeb84d7983f7cd290e34417de769fa032 Mon Sep 17 00:00:00 2001 From: Zachary Rogers Date: Thu, 29 Aug 2024 21:05:22 -0700 Subject: [PATCH 2/4] devex: Update tests to use new logger. Allow logger context to be introspected. --- .../cognito-authorizer.test.ts | 102 +++++------------ .../websocket-authorizer.test.ts | 103 ++++++------------ web-api/src/logger.test.ts | 43 +++----- web-api/src/utilities/logger/getLogger.ts | 2 + 4 files changed, 81 insertions(+), 169 deletions(-) diff --git a/web-api/src/lambdas/cognitoAuthorizer/cognito-authorizer.test.ts b/web-api/src/lambdas/cognitoAuthorizer/cognito-authorizer.test.ts index b3526210871..3046295cadb 100644 --- a/web-api/src/lambdas/cognitoAuthorizer/cognito-authorizer.test.ts +++ b/web-api/src/lambdas/cognitoAuthorizer/cognito-authorizer.test.ts @@ -1,15 +1,17 @@ -import { createLogger } from '../../createLogger'; import { handler } from './cognito-authorizer'; -import { transports } from 'winston'; import axios from 'axios'; -import fs from 'fs'; import jwk from 'jsonwebtoken'; -const { createLogger: actualCreateLogger } = jest.requireActual( - '../../../src/createLogger', -); -jest.mock('../../../src/createLogger', () => { - return { createLogger: jest.fn() }; +const mockLogger = { + addContext: jest.fn(), + clearContext: jest.fn(), + info: jest.fn(), + warn: jest.fn(), +}; +jest.mock('@web-api/utilities/logger/getLogger', () => { + return { + getLogger: () => mockLogger, + }; }); jest.mock('jsonwebtoken', () => { return { @@ -48,18 +50,9 @@ describe('cognito-authorizer', () => { }); }; - let event, context, transport; + let event, context; beforeEach(() => { - transport = new transports.Stream({ - stream: fs.createWriteStream('/dev/null'), - }); - - (createLogger as jest.Mock).mockImplementation(opts => { - opts.transports = [transport]; - return actualCreateLogger(opts); - }); - event = { authorizationToken: 'Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJlbWFpbCI6ImFkbWlzc2lvbnNjbGVya0BleGFtcGxlLmNvbSIsIm5hbWUiOiJUZXN0IEFkbWlzc2lvbnMgQ2xlcmsiLCJyb2xlIjoiYWRtaXNzaW9uc2NsZXJrIiwic2VjdGlvbiI6ImFkbWlzc2lvbnMiLCJ1c2VySWQiOiI5ZDdkNjNiNy1kN2E1LTQ5MDUtYmE4OS1lZjcxYmYzMDA1N2YiLCJjdXN0b206cm9sZSI6ImFkbWlzc2lvbnNjbGVyayIsInN1YiI6IjlkN2Q2M2I3LWQ3YTUtNDkwNS1iYTg5LWVmNzFiZjMwMDU3ZiIsImlhdCI6MTYwOTQ0NTUyNn0.kow3pAUloDseD3isrxgtKBpcKsjMktbRBzY41c1NRqA', @@ -79,7 +72,6 @@ describe('cognito-authorizer', () => { }); jest.spyOn(axios, 'get'); - jest.spyOn(transport, 'log'); }); it('returns unauthorized when token is missing', async () => { @@ -87,12 +79,8 @@ describe('cognito-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('No authorizationToken found'), - }), - expect.any(Function), + expect(mockLogger.info).toHaveBeenCalledWith( + 'No authorizationToken found in the header', ); }); @@ -103,15 +91,9 @@ describe('cognito-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'Could not fetch keys for token issuer', - ), - stack: expect.stringContaining('Error: any error'), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'Could not fetch keys for token issuer, considering request unauthorized', + new Error('any error'), ); }); @@ -122,15 +104,9 @@ describe('cognito-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'Could not fetch keys for token issuer', - ), - stack: expect.any(String), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'Could not fetch keys for token issuer, considering request unauthorized', + expect.anything(), ); }); @@ -143,17 +119,13 @@ describe('cognito-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( + expect(mockLogger.warn).toHaveBeenCalledWith( + 'The key used to sign the authorization token was not found in the user pool’s keys, considering request unauthorized', expect.objectContaining({ issuer: expect.any(String), keys: expect.any(Array), - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'was not found in the user pool’s keys', - ), requestedKeyId: 'key-identifier', }), - expect.any(Function), ); }); @@ -175,13 +147,9 @@ describe('cognito-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining('token is not valid'), - stack: expect.stringContaining('Error: verification failed'), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'The token is not valid, considering request unauthorized', + new Error('verification failed'), ); }); @@ -207,14 +175,9 @@ describe('cognito-authorizer', () => { }), ); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('Request authorized'), - metadata: expect.objectContaining({ policy }), - }), - expect.any(Function), - ); + expect(mockLogger.info).toHaveBeenCalledWith('Request authorized', { + metadata: { policy }, + }); }); it('returns IAM policy to allow invoking requested lambda when authorized using the payload custom:userId', async () => { @@ -239,14 +202,9 @@ describe('cognito-authorizer', () => { }), ); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('Request authorized'), - metadata: expect.objectContaining({ policy }), - }), - expect.any(Function), - ); + expect(mockLogger.info).toHaveBeenCalledWith('Request authorized', { + metadata: { policy }, + }); }); it('caches keys for issuers', async () => { diff --git a/web-api/src/lambdas/cognitoAuthorizer/websocket-authorizer.test.ts b/web-api/src/lambdas/cognitoAuthorizer/websocket-authorizer.test.ts index d3b03fbc0b1..3569907db1c 100644 --- a/web-api/src/lambdas/cognitoAuthorizer/websocket-authorizer.test.ts +++ b/web-api/src/lambdas/cognitoAuthorizer/websocket-authorizer.test.ts @@ -1,14 +1,17 @@ -const { createLogger: actualCreateLogger } = jest.requireActual( - '../../../src/createLogger', -); -import { createLogger } from '../../createLogger'; import { handler } from './websocket-authorizer'; -import { transports } from 'winston'; import axios from 'axios'; -import fs from 'fs'; import jwk from 'jsonwebtoken'; -jest.mock('../../../src/createLogger', () => { - return { createLogger: jest.fn() }; + +const mockLogger = { + addContext: jest.fn(), + clearContext: jest.fn(), + info: jest.fn(), + warn: jest.fn(), +}; +jest.mock('@web-api/utilities/logger/getLogger', () => { + return { + getLogger: () => mockLogger, + }; }); jest.mock('jsonwebtoken', () => { return { @@ -47,18 +50,9 @@ describe('websocket-authorizer', () => { }); }; - let event, context, transport; + let event, context; beforeEach(() => { - transport = new transports.Stream({ - stream: fs.createWriteStream('/dev/null'), - }); - - createLogger.mockImplementation(opts => { - opts.transports = [transport]; - return actualCreateLogger(opts); - }); - event = { methodArn: 'arn:aws:execute-api:us-east-1:aws-account-id:api-gateway-id/stage/GET/path', @@ -75,7 +69,6 @@ describe('websocket-authorizer', () => { }; jest.spyOn(axios, 'get'); - jest.spyOn(transport, 'log'); jwk.decode.mockReturnValue({ header: { kid: 'key-identifier' }, @@ -88,12 +81,8 @@ describe('websocket-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('No authorizationToken found'), - }), - expect.any(Function), + expect(mockLogger.info).toHaveBeenCalledWith( + 'No authorizationToken found in the header', ); }); @@ -104,15 +93,9 @@ describe('websocket-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'Could not fetch keys for token issuer', - ), - stack: expect.stringContaining('Error: any error'), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'Could not fetch keys for token issuer, considering request unauthorized', + new Error('any error'), ); }); @@ -123,15 +106,9 @@ describe('websocket-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'Could not fetch keys for token issuer', - ), - stack: expect.any(String), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'Could not fetch keys for token issuer, considering request unauthorized', + expect.anything(), ); }); @@ -144,17 +121,13 @@ describe('websocket-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( + expect(mockLogger.warn).toHaveBeenCalledWith( + 'The key used to sign the authorization token was not found in the user pool’s keys, considering request unauthorized', expect.objectContaining({ issuer: expect.any(String), keys: expect.any(Array), - level: expect.stringContaining('warning'), - message: expect.stringContaining( - 'was not found in the user pool’s keys', - ), requestedKeyId: 'key-identifier', }), - expect.any(Function), ); }); @@ -176,13 +149,9 @@ describe('websocket-authorizer', () => { await expect(() => handler(event, context)).rejects.toThrow('Unauthorized'); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('warning'), - message: expect.stringContaining('token is not valid'), - stack: expect.stringContaining('Error: verification failed'), - }), - expect.any(Function), + expect(mockLogger.warn).toHaveBeenCalledWith( + 'The token is not valid, considering request unauthorized', + expect.anything(), ); }); @@ -208,14 +177,9 @@ describe('websocket-authorizer', () => { }), ); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('Request authorized'), - metadata: expect.objectContaining({ policy }), - }), - expect.any(Function), - ); + expect(mockLogger.info).toHaveBeenCalledWith('Request authorized', { + metadata: { policy }, + }); }); it('returns IAM policy to allow invoking requested lambda when authorized using the payload custom:userId', async () => { @@ -240,14 +204,9 @@ describe('websocket-authorizer', () => { }), ); - expect(transport.log).toHaveBeenCalledWith( - expect.objectContaining({ - level: expect.stringContaining('info'), - message: expect.stringContaining('Request authorized'), - metadata: expect.objectContaining({ policy }), - }), - expect.any(Function), - ); + expect(mockLogger.info).toHaveBeenCalledWith('Request authorized', { + metadata: { policy }, + }); }); it('caches keys for issuers', async () => { diff --git a/web-api/src/logger.test.ts b/web-api/src/logger.test.ts index d8f1dfe8a34..ac23105cdbd 100644 --- a/web-api/src/logger.test.ts +++ b/web-api/src/logger.test.ts @@ -1,6 +1,4 @@ import { expressLogger } from './logger'; -import { transports } from 'winston'; -import fs from 'fs'; jest.mock('@vendia/serverless-express'); import { getCurrentInvoke } from '@vendia/serverless-express'; @@ -36,11 +34,7 @@ describe('logger', () => { const subject = (request, response) => new Promise(resolve => { - const middleware = expressLogger( - new transports.Stream({ - stream: fs.createWriteStream('/dev/null'), - }), - ); + const middleware = expressLogger; middleware(request, response, resolve); }); @@ -51,7 +45,7 @@ describe('logger', () => { }); it('defaults to using a console logger if not specified', () => { - const middleware = expressLogger(); + const middleware = expressLogger; jest.spyOn(console, 'log').mockImplementation(jest.fn()); middleware(req, res, () => { @@ -80,7 +74,7 @@ describe('logger', () => { ); }); - it('sets logger.defaultMeta.environment color stage to from the environment variables', async () => { + it('sets logger.getContext().environment based on environment variables and clears the context at the end of the request', async () => { process.env.NODE_ENV = 'production'; process.env.CURRENT_COLOR = 'blue'; process.env.STAGE = 'someEnv'; @@ -88,16 +82,16 @@ describe('logger', () => { await subject(req, res); const instance = req.locals.logger; - instance.info = jest.fn(); - - res.end(); - expect(instance.defaultMeta.environment).toEqual({ + expect(instance.getContext().environment).toEqual({ color: 'blue', stage: 'someEnv', }); + + res.end(); + expect(instance.getContext()).toEqual(undefined); }); - it('sets logger.defaultMeta.environment color to green and stage to local when those environment variables are undefined', async () => { + it('sets logger.getContext().environment color to green and stage to local when those environment variables are undefined', async () => { delete process.env.CURRENT_COLOR; delete process.env.STAGE; process.env.NODE_ENV = 'production'; @@ -107,8 +101,7 @@ describe('logger', () => { instance.info = jest.fn(); - res.end(); - expect(instance.defaultMeta.environment).toEqual({ + expect(instance.getContext().environment).toEqual({ color: 'green', stage: 'local', }); @@ -137,14 +130,14 @@ describe('logger', () => { await subject(req, res); - expect(req.locals.logger.defaultMeta.requestId).toBeDefined(); - expect(req.locals.logger.defaultMeta.requestId.apiGateway).toBe( + expect(req.locals.logger.getContext().requestId).toBeDefined(); + expect(req.locals.logger.getContext().requestId.apiGateway).toBe( '11ff704e-b35b-4472-8280-29be3fb957ca', ); expect( - req.locals.logger.defaultMeta.requestId.applicationLoadBalancer, + req.locals.logger.getContext().requestId.applicationLoadBalancer, ).toBe('Root=1-5fa1efc9-164cfd9602fe2b523bf82292;Sampled=0'); - expect(req.locals.logger.defaultMeta.requestId.lambda).toBe( + expect(req.locals.logger.getContext().requestId.lambda).toBe( 'c840522b-1e43-4d03-995c-014d199fa237', ); }); @@ -176,15 +169,15 @@ describe('logger', () => { await subject(request, res); - expect(request.locals.logger.defaultMeta.requestId).toBeDefined(); + expect(request.locals.logger.getContext().requestId).toBeDefined(); expect( - request.locals.logger.defaultMeta.requestId.apiGateway, + request.locals.logger.getContext().requestId.apiGateway, ).not.toBeDefined(); expect( - request.locals.logger.defaultMeta.requestId.applicationLoadBalancer, + request.locals.logger.getContext().requestId.applicationLoadBalancer, ).not.toBeDefined(); expect( - request.locals.logger.defaultMeta.requestId.lambda, + request.locals.logger.getContext().requestId.lambda, ).not.toBeDefined(); } }); @@ -216,7 +209,7 @@ describe('logger', () => { await subject(req, res); const bodyToBeLogged = JSON.parse( - req.locals.logger.defaultMeta.request.body, + req.locals.logger.getContext().request.body, ); expect(bodyToBeLogged.username).toBe(body.username); diff --git a/web-api/src/utilities/logger/getLogger.ts b/web-api/src/utilities/logger/getLogger.ts index 13bef67b4e2..c778d2c3948 100644 --- a/web-api/src/utilities/logger/getLogger.ts +++ b/web-api/src/utilities/logger/getLogger.ts @@ -18,6 +18,7 @@ export const getLogger = (): LoggerType => { }, debug: (message, context?) => logger.debug(message, { context }), error: (message, context?) => logger.error(message, { context }), + getContext: () => logger.defaultMeta, info: (message, context?) => logger.info(message, { context }), warn: (message, context?) => logger.warn(message, { context }), }; @@ -33,4 +34,5 @@ type LoggerType = { warn: (message: any, context?: any) => Logger; clearContext: () => void; addContext: (newMeta: Record) => void; + getContext: () => Record; }; From fa087906a0226ac6a9393a478cb2b7c48d482c58 Mon Sep 17 00:00:00 2001 From: Zachary Rogers Date: Thu, 29 Aug 2024 21:17:06 -0700 Subject: [PATCH 3/4] devex: remove console log --- web-api/src/genericHandler.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/web-api/src/genericHandler.ts b/web-api/src/genericHandler.ts index 920c1763704..99b85493a6a 100644 --- a/web-api/src/genericHandler.ts +++ b/web-api/src/genericHandler.ts @@ -85,8 +85,6 @@ export const genericHandler = ( return handle(awsEvent, async () => { const user = getUserFromAuthHeader(awsEvent); const clientConnectionId = getConnectionIdFromEvent(awsEvent); - // pinkLog('I am the event logger', awsEvent.logger); - console.log('I am awsEvent: ', awsEvent); const applicationContext = createApplicationContext(user); delete awsEvent.logger; From bc3ff1a0e89155142cccb3958bf20abc062e46be Mon Sep 17 00:00:00 2001 From: Zachary Rogers Date: Mon, 2 Sep 2024 09:09:43 -0700 Subject: [PATCH 4/4] devex: Remove user from needing to be passed into applicationContext. Instead add context to the logger. --- web-api/src/applicationContext.ts | 11 ++--------- web-api/src/gateways/worker/workerLocal.ts | 4 +++- web-api/src/genericHandler.ts | 4 +++- .../src/lambdas/cases/sealInLowerEnvironmentLambda.ts | 4 +++- .../src/lambdas/cognitoAuthorizer/worker-handler.ts | 4 +++- web-api/src/lambdas/migration/migration-segments.ts | 2 +- web-api/src/lambdas/migration/migration.ts | 2 +- web-api/src/lambdas/pdfGeneration/pdf-generation.ts | 4 +++- web-api/src/middleware/userIdLimiter.ts | 4 +++- web-api/src/utilities/logger/getLogger.ts | 8 ++++++++ web-api/storage/scripts/createUsers.ts | 11 +++++++++-- 11 files changed, 39 insertions(+), 19 deletions(-) diff --git a/web-api/src/applicationContext.ts b/web-api/src/applicationContext.ts index 2129a441503..1943fac5323 100644 --- a/web-api/src/applicationContext.ts +++ b/web-api/src/applicationContext.ts @@ -96,15 +96,8 @@ const entitiesByName = { WorkItem, }; +// eslint-disable-next-line @typescript-eslint/no-unused-vars export const createApplicationContext = (appContextUser = {}) => { - const user = new User(appContextUser); - const logger = getLogger(); - if (process.env.NODE_ENV === 'production') { - const authenticated = user && Object.keys(user).length; - const userForLogging = authenticated ? user : { role: 'unauthenticated' }; - logger.addContext({ user: userForLogging }); - } - return { barNumberGenerator, docketNumberGenerator, @@ -276,7 +269,7 @@ export const createApplicationContext = (appContextUser = {}) => { }), isAuthorized, isCurrentColorActive, - logger, + logger: getLogger(), setTimeout: (callback, timeout) => setTimeout(callback, timeout), }; }; diff --git a/web-api/src/gateways/worker/workerLocal.ts b/web-api/src/gateways/worker/workerLocal.ts index 458e8116ca2..cdd088014c5 100644 --- a/web-api/src/gateways/worker/workerLocal.ts +++ b/web-api/src/gateways/worker/workerLocal.ts @@ -7,13 +7,15 @@ import { WorkerMessage, workerRouter, } from '@web-api/gateways/worker/workerRouter'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; export const workerLocal: WorkerHandler = async ( applicationContext: ServerApplicationContext, { message }: { message: WorkerMessage }, ): Promise => { // Simulate what happens on a deployed environment when a message is sent to SQS. - const appContext = createApplicationContext(message.authorizedUser); + const appContext = createApplicationContext(); + getLogger().addUser({ user: message.authorizedUser }); setTimeout( async () => { try { diff --git a/web-api/src/genericHandler.ts b/web-api/src/genericHandler.ts index 99b85493a6a..b8b5a59326b 100644 --- a/web-api/src/genericHandler.ts +++ b/web-api/src/genericHandler.ts @@ -8,6 +8,7 @@ import { getUserFromAuthHeader, handle, } from './middleware/apiGatewayHelper'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; export const dataSecurityFilter = ( data, @@ -85,7 +86,8 @@ export const genericHandler = ( return handle(awsEvent, async () => { const user = getUserFromAuthHeader(awsEvent); const clientConnectionId = getConnectionIdFromEvent(awsEvent); - const applicationContext = createApplicationContext(user); + const applicationContext = createApplicationContext(); + getLogger().addUser({ user }); delete awsEvent.logger; diff --git a/web-api/src/lambdas/cases/sealInLowerEnvironmentLambda.ts b/web-api/src/lambdas/cases/sealInLowerEnvironmentLambda.ts index 694b9a4fb56..f55e17f2404 100644 --- a/web-api/src/lambdas/cases/sealInLowerEnvironmentLambda.ts +++ b/web-api/src/lambdas/cases/sealInLowerEnvironmentLambda.ts @@ -1,5 +1,6 @@ import { AuthUser } from '@shared/business/entities/authUser/AuthUser'; import { createApplicationContext } from '../../applicationContext'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { sealInLowerEnvironment } from '@web-api/business/useCaseHelper/sealInLowerEnvironment'; /** @@ -16,7 +17,8 @@ export const sealInLowerEnvironmentLambda = async event => { userId: 'N/A', }; - const applicationContext = createApplicationContext(user); + const applicationContext = createApplicationContext(); + getLogger().addUser({ user }); const records = event.Records.map(record => ({ ...JSON.parse(record.Sns.Message), diff --git a/web-api/src/lambdas/cognitoAuthorizer/worker-handler.ts b/web-api/src/lambdas/cognitoAuthorizer/worker-handler.ts index f9deadf3861..0ee8486f3de 100644 --- a/web-api/src/lambdas/cognitoAuthorizer/worker-handler.ts +++ b/web-api/src/lambdas/cognitoAuthorizer/worker-handler.ts @@ -4,11 +4,13 @@ import { workerRouter, } from '@web-api/gateways/worker/workerRouter'; import { createApplicationContext } from '@web-api/applicationContext'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; export const workerHandler = async (event: SQSEvent): Promise => { const { Records } = event; const { body } = Records[0]; const message: WorkerMessage = JSON.parse(body); - const applicationContext = createApplicationContext(message.authorizedUser); + const applicationContext = createApplicationContext(); + getLogger().addUser({ user: message.authorizedUser }); await workerRouter(applicationContext, { message }); }; diff --git a/web-api/src/lambdas/migration/migration-segments.ts b/web-api/src/lambdas/migration/migration-segments.ts index 1060aa2a2ac..4958cf51447 100644 --- a/web-api/src/lambdas/migration/migration-segments.ts +++ b/web-api/src/lambdas/migration/migration-segments.ts @@ -150,7 +150,7 @@ export const processItems = async ( }; export const handler: Handler = async (event: SQSEvent, context: Context) => { - const applicationContext = createApplicationContext({}); + const applicationContext = createApplicationContext(); getLogger().clearContext(); getLogger().addContext({ environment: { diff --git a/web-api/src/lambdas/migration/migration.ts b/web-api/src/lambdas/migration/migration.ts index d94a47a1a5e..748d38f319a 100644 --- a/web-api/src/lambdas/migration/migration.ts +++ b/web-api/src/lambdas/migration/migration.ts @@ -61,7 +61,7 @@ export const handler: Handler = async (event: DynamoDBStreamEvent, context) => { marshallOptions: { removeUndefinedValues: true }, }); - const applicationContext = createApplicationContext({}); + const applicationContext = createApplicationContext(); getLogger().clearContext(); getLogger().addContext({ environment: { diff --git a/web-api/src/lambdas/pdfGeneration/pdf-generation.ts b/web-api/src/lambdas/pdfGeneration/pdf-generation.ts index 2154661bf2e..7c55a3cfe35 100644 --- a/web-api/src/lambdas/pdfGeneration/pdf-generation.ts +++ b/web-api/src/lambdas/pdfGeneration/pdf-generation.ts @@ -1,4 +1,5 @@ import { createApplicationContext } from '../../applicationContext'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; export const handler = async event => { const applicationContext = createApplicationContext({}); @@ -28,7 +29,8 @@ export const changeOfAddressHandler = async event => { const { body } = Records[0]; const eventBody = JSON.parse(body); - const applicationContext = createApplicationContext(eventBody.requestUser); + const applicationContext = createApplicationContext(); + getLogger().addUser({ user: eventBody.requestUser }); applicationContext.logger.info( `processing job "change-of-address-job|${eventBody.jobId}", task for case ${eventBody.docketNumber}`, diff --git a/web-api/src/middleware/userIdLimiter.ts b/web-api/src/middleware/userIdLimiter.ts index 2212a1ea590..7058d046a11 100644 --- a/web-api/src/middleware/userIdLimiter.ts +++ b/web-api/src/middleware/userIdLimiter.ts @@ -1,4 +1,5 @@ import { createApplicationContext } from '../applicationContext'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { getUserFromAuthHeader } from './apiGatewayHelper'; export const userIdLimiter = key => async (req, res, next) => { @@ -8,7 +9,8 @@ export const userIdLimiter = key => async (req, res, next) => { const WINDOW_TIME = parseInt( process.env.USER_LIMITER_WINDOW ?? `${60 * 1000}`, ); - const applicationContext = createApplicationContext(user); + const applicationContext = createApplicationContext(); + getLogger().addUser({ user }); const KEY = `user-limiter-${key}|${user.userId}`; const limiterCache = await applicationContext diff --git a/web-api/src/utilities/logger/getLogger.ts b/web-api/src/utilities/logger/getLogger.ts index c778d2c3948..e61864aa6dc 100644 --- a/web-api/src/utilities/logger/getLogger.ts +++ b/web-api/src/utilities/logger/getLogger.ts @@ -1,4 +1,5 @@ import { Logger } from 'winston'; +import { UnknownAuthUser } from '@shared/business/entities/authUser/AuthUser'; import { createLogger } from '@web-api/createLogger'; let loggerCache: LoggerType; @@ -13,6 +14,12 @@ export const getLogger = (): LoggerType => { ...newMeta, }; }, + addUser: ({ user }: { user: UnknownAuthUser }) => { + logger.defaultMeta = { + ...logger.defaultMeta, + user, + }; + }, clearContext: () => { logger.defaultMeta = undefined; }, @@ -28,6 +35,7 @@ export const getLogger = (): LoggerType => { }; type LoggerType = { + addUser: (user: { user: UnknownAuthUser }) => void; debug: (message: any, context?: any) => Logger; error: (message: any, context?: any) => Logger; info: (message: any, context?: any) => Logger; diff --git a/web-api/storage/scripts/createUsers.ts b/web-api/storage/scripts/createUsers.ts index 8e5489fcc5c..93779f64e29 100644 --- a/web-api/storage/scripts/createUsers.ts +++ b/web-api/storage/scripts/createUsers.ts @@ -6,6 +6,7 @@ import { import { createApplicationContext } from '../../src/applicationContext'; import { createPetitionerUserRecords } from '../../../web-api/src/persistence/dynamo/users/createPetitionerUserRecords'; import { createUserRecords } from '../../src/persistence/dynamo/users/createUserRecords'; +import { getLogger } from '@web-api/utilities/logger/getLogger'; import { omit } from 'lodash'; import users from '../fixtures/seed/users.json'; @@ -13,8 +14,14 @@ export const createUsers = async () => { const EXCLUDE_PROPS = ['pk', 'sk', 'userId']; const usersByEmail = {}; - const applicationContext = createApplicationContext({ - role: ROLES.admin, + const applicationContext = createApplicationContext(); + getLogger().addUser({ + user: { + email: 'system@ustc.gov', + name: 'ustc automated system', + role: ROLES.admin, + userId: 'N/A', + }, }); await Promise.all(