diff --git a/src/commands/serve/handler.spec.ts b/src/commands/serve/handler.spec.ts index 746cd111..06d673ae 100644 --- a/src/commands/serve/handler.spec.ts +++ b/src/commands/serve/handler.spec.ts @@ -7,6 +7,7 @@ import stripAnsi from 'strip-ansi' import { LoadConfig, LoadConfigStatus } from '~config/load' import { TypeValidator } from '~validation' import { ConfigBuilder } from '~config/types' +import { Logger } from './server/server-logger' jest.unmock('./handler') jest.unmock('@hapi/joi') @@ -19,18 +20,27 @@ describe('handler', () => { const mockStartServer = mockFn() const mockChokidar = mockObj(chokidar) const mockLoadConfig = mockFn>() + const mockLogger = mockObj({}) + const mockCreateLogger = jest.fn() - const handler = createHandler(mockHandleError, mockCreateTypeValidator, mockStartServer, mockLoadConfig) + const handler = createHandler( + mockHandleError, + mockCreateTypeValidator, + mockStartServer, + mockLoadConfig, + mockCreateLogger, + ) beforeEach(() => { jest.resetAllMocks() mockChokidar.watch.mockReturnValue( mockObj({ on: jest.fn() }), ) + mockCreateLogger.mockReturnValue(mockLogger) }) it('handles when a config path is not supplied', async () => { - await handler({ force: false, port: 8001, tsconfigPath: randomString(), watch: false }) + await handler({ force: false, port: 8001, tsconfigPath: randomString(), watch: false, verbose: false }) expect(mockHandleError).toBeCalledWith({ message: 'config path must be supplied' }) }) @@ -42,6 +52,7 @@ describe('handler', () => { tsconfigPath: randomString(), configPath: randomString(), watch: false, + verbose: false, }) expect(mockHandleError).toBeCalledWith({ message: 'port must be a number' }) @@ -54,6 +65,7 @@ describe('handler', () => { tsconfigPath: randomString(), configPath: randomString(), watch: true, + verbose: false, }) expect(mockHandleError).toBeCalledWith({ message: 'watch and force options cannot be used together' }) @@ -65,6 +77,7 @@ describe('handler', () => { tsconfigPath: randomString(), configPath: randomString(), watch: false, + verbose: false, } describe('runs the server with the correct configs', () => { @@ -77,6 +90,7 @@ describe('handler', () => { mockTransformConfigs.mockResolvedValue([ { name: randomString('name'), request: {}, response: {} } as ServeConfig, ]) + mockCreateLogger.mockReturnValue(mockLogger) }) it('calls loadconfig with the correct args', async () => { @@ -147,7 +161,7 @@ describe('handler', () => { expect(mockHandleError).not.toBeCalled() expect(mockStartServer).toBeCalledTimes(1) - expect(mockStartServer).toBeCalledWith(args.port, configs, mockTypeValidator) + expect(mockStartServer).toBeCalledWith(args.port, configs, mockTypeValidator, mockLogger) }) }) }) diff --git a/src/commands/serve/handler.ts b/src/commands/serve/handler.ts index 2aed630a..f1e56690 100644 --- a/src/commands/serve/handler.ts +++ b/src/commands/serve/handler.ts @@ -8,6 +8,7 @@ import { StartServerResult } from './server' import { LoadConfig, LoadConfigStatus } from '~config/load' import { red } from 'chalk' import { logMetric } from '~metrics' +import { Logger } from './server/server-logger' export interface ServeArgs { configPath?: string @@ -16,12 +17,14 @@ export interface ServeArgs { schemaPath?: string force: boolean watch: boolean + verbose: boolean } export type StartServer = ( port: number, routes: ServeConfig[], - typeValidator?: TypeValidator, + typeValidator: TypeValidator | undefined, + logger: Logger, ) => StartServerResult const ATTEMPT_RESTARTING_MSG = 'Attempting to restart ncdc server' @@ -41,9 +44,10 @@ const createHandler = ( createTypeValidator: CreateServeTypeValidator, startServer: StartServer, loadConfig: LoadConfig, + getServerLogger: (verbose: boolean) => Logger, ) => async (args: ServeArgs): Promise => { logMetric('Program start') - const { configPath, port, tsconfigPath, schemaPath, force, watch } = args + const { configPath, port, tsconfigPath, schemaPath, force, watch, verbose } = args if (!configPath) return handleError({ message: 'config path must be supplied' }) if (isNaN(port)) return handleError({ message: 'port must be a number' }) @@ -98,7 +102,7 @@ const createHandler = ( throw new Error('An unknown error ocurred') } - const startServerResult = startServer(port, loadResult.configs, typeValidator) + const startServerResult = startServer(port, loadResult.configs, typeValidator, getServerLogger(verbose)) return { startServerResult, pathsToWatch: loadResult.absoluteFixturePaths, diff --git a/src/commands/serve/index.ts b/src/commands/serve/index.ts index 0dcced65..68f3a396 100644 --- a/src/commands/serve/index.ts +++ b/src/commands/serve/index.ts @@ -10,6 +10,7 @@ import Ajv from 'ajv' import { FsSchemaLoader, SchemaRetriever, WatchingSchemaGenerator } from '~schema' import { SchemaGenerator } from '~schema' import { logMetric } from '~metrics' +import createServerLogger, { Logger } from './server/server-logger' const builder = (yargs: Argv): Argv => yargs @@ -68,10 +69,13 @@ export default function createServeCommand() { return new TypeValidator(ajv, schemaRetriever) } + const makeServerLogger = (verbose: boolean): Logger => + createServerLogger(process.env.LOG_LEVEL ?? (verbose ? 'verbose' : 'info')) + return { command: 'serve [port]', describe: 'Serves configured endpoints', builder, - handler: createHandler(handleError, getTypeValidator, startServer, loadConfig), + handler: createHandler(handleError, getTypeValidator, startServer, loadConfig, makeServerLogger), } } diff --git a/src/commands/serve/server/index.ts b/src/commands/serve/server/index.ts index 7827fac5..6e250790 100644 --- a/src/commands/serve/server/index.ts +++ b/src/commands/serve/server/index.ts @@ -2,7 +2,7 @@ import express, { Express, Request, Response, ErrorRequestHandler } from 'expres import { blue } from 'chalk' import { Server } from 'http' import { TypeValidator } from '~validation' -import serverLogger from './server-logger' +import { Logger } from './server-logger' import { inspect } from 'util' import { ServeConfig } from '../config' import validateQuery from './query-validator' @@ -45,26 +45,27 @@ const mapLog = ( }, }) -const handleError: ErrorRequestHandler = (err: Error, req, res, next) => { - if (res.headersSent) return next() - - const { method, path, query, headers, body } = req - serverLogger.error( - `Error while serving ${inspect({ method, path, query, headers, body }, false, undefined, true)}`, - err, - ) - res.status(500).send(err.stack?.toString() ?? err.toString()) -} - export const configureServer = ( baseUrl: string, mockConfigs: ServeConfig[], - typeValidator?: TypeValidator, + typeValidator: TypeValidator | undefined, + logger: Logger, ): Express => { const app = express() const ROOT = '/' const ignoredLogPaths = [ROOT] + const handleError: ErrorRequestHandler = (err: Error, req, res, next) => { + if (res.headersSent) return next() + + const { method, path, query, headers, body } = req + logger.error( + `Error while serving ${inspect({ method, path, query, headers, body }, false, undefined, true)}`, + err, + ) + res.status(500).send(err.stack?.toString() ?? err.toString()) + } + app.use(handleError) app.use(express.text()) app.use(express.json()) @@ -72,7 +73,7 @@ export const configureServer = ( app.get(ROOT, (_, res) => res.json(mockConfigs)) if (mockConfigs.length === 0) { - serverLogger.info('No mocks to serve') + logger.info('No mocks to serve') } mockConfigs.forEach(({ name, request, response }) => { @@ -82,7 +83,7 @@ export const configureServer = ( try { const queryIsValid = validateQuery(request.endpoint, req.query) if (!queryIsValid) { - serverLogger.warn( + logger.warn( `An endpoint for ${req.path} exists but the query params did not match the configuration`, ) return next() @@ -91,9 +92,7 @@ export const configureServer = ( if (typeValidator && request.type) { const validationResult = await typeValidator.validate(req.body, request.type) if (!validationResult.success) { - serverLogger.warn( - `An endpoint for ${req.path} exists but the request body did not match the type`, - ) + logger.warn(`An endpoint for ${req.path} exists but the request body did not match the type`) // TODO: something like this to capture better response codes // res.locals.status = 400 @@ -112,7 +111,7 @@ export const configureServer = ( bodyToLog = `${shortenedBody}${shortenedBody && shortenedBody.length >= 30 ? '...' : ''}` } - serverLogger.info(mapLog(name, req, res, bodyToLog)) + logger.info(mapLog(name, req, res, bodyToLog)) } res.send(response.body) @@ -120,7 +119,7 @@ export const configureServer = ( handleError(err, req, res, next) } }) - serverLogger.info(`Registered ${baseUrl}${request.endpoint} from config: ${blue(name)}`) + logger.verbose(`Registered ${baseUrl}${request.endpoint} from config: ${blue(name)}`) }) const default404Response = @@ -135,7 +134,7 @@ export const configureServer = ( const responseBody = status === 404 ? default404Response : `NCDC: ${res.locals.message}` if (!ignoredLogPaths.includes(req.path)) { - serverLogger.error(mapLog(undefined, req, res, responseBody.replace(/\n+/g, ' '))) + logger.error(mapLog(undefined, req, res, responseBody.replace(/\n+/g, ' '))) } res.send(responseBody) @@ -155,13 +154,14 @@ export interface StartServerResult { export const startServer = ( port: number, routes: ServeConfig[], - typeValidator?: TypeValidator, + typeValidator: TypeValidator | undefined, + logger: Logger, ): StartServerResult => { const serverRoot = `http://localhost:${port}` - const app = configureServer(serverRoot, routes, typeValidator) + const app = configureServer(serverRoot, routes, typeValidator, logger) const server = app.listen(port, () => { - serverLogger.info(`Endpoints are being served on ${serverRoot}`) + logger.info(`Endpoints are being served on ${serverRoot}`) logMetric('Server is listening') }) diff --git a/src/commands/serve/server/server-logger.ts b/src/commands/serve/server/server-logger.ts index ce2aebe5..c08da38c 100644 --- a/src/commands/serve/server/server-logger.ts +++ b/src/commands/serve/server/server-logger.ts @@ -1,36 +1,39 @@ -import { createLogger, format, transports } from 'winston' +import { createLogger, format, transports, Logger as WinstonLogger } from 'winston' import { inspect } from 'util' import escapeStringRegexp from 'escape-string-regexp' -const serverLogger = createLogger({ - exitOnError: false, - transports: [ - new transports.Console({ - handleExceptions: true, - level: 'debug', - format: format.combine( - format.colorize(), - format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }), - format.errors({ stack: true }), - format.printf((info) => { - let result = `${info.timestamp} - ${info.level}: ` +export type Logger = WinstonLogger - let message = - typeof info.message === 'object' ? inspect(info.message, false, 4, true) : info.message +export const createServerLogger = (logLevel: string): Logger => + createLogger({ + exitOnError: false, + transports: [ + new transports.Console({ + handleExceptions: true, + level: logLevel, + format: format.combine( + format.colorize(), + format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }), + format.errors({ stack: true }), + format.printf((info) => { + let result = `${info.timestamp} - ${info.level}: ` - const matchedError = info.stack?.match(/Error: (.*)/) - if (matchedError && matchedError[1]) { - const escapedMatch = escapeStringRegexp(matchedError[1]) - message = message.replace(new RegExp(`${escapedMatch}$`), '') - } + let message = + typeof info.message === 'object' ? inspect(info.message, false, 4, true) : info.message - result += message - result += info.stack ? `\n${info.stack}` : '' - return result - }), - ), - }), - ], -}) + const matchedError = info.stack?.match(/Error: (.*)/) + if (matchedError && matchedError[1]) { + const escapedMatch = escapeStringRegexp(matchedError[1]) + message = message.replace(new RegExp(`${escapedMatch}$`), '') + } -export default serverLogger + result += message + result += info.stack ? `\n${info.stack}` : '' + return result + }), + ), + }), + ], + }) + +export default createServerLogger diff --git a/src/commands/serve/server/server.integration.spec.ts b/src/commands/serve/server/server.integration.spec.ts index bf5ada6d..cc11a0f9 100644 --- a/src/commands/serve/server/server.integration.spec.ts +++ b/src/commands/serve/server/server.integration.spec.ts @@ -2,22 +2,30 @@ import request from 'supertest' import { configureServer, verbsMap, PossibleMethod, ReqResLog } from '.' import { ConfigBuilder, SupportedMethod } from '~config/types' import { TypeValidator } from '~validation' -import { mockObj, mocked } from '~test-helpers' -import serverLogger from './server-logger' - -jest.mock('./server-logger') +import { mockObj } from '~test-helpers' +import { Logger } from './server-logger' +import { ServeConfig } from '../config' describe('server', () => { jest.spyOn(console, 'dir').mockImplementation() const mockTypeValidator = mockObj({ validate: jest.fn() }) + const mockLogger = mockObj({ + info: jest.fn(), + verbose: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + }) afterEach(() => jest.resetAllMocks()) afterAll(() => jest.clearAllMocks()) + const getApp = (configs: ServeConfig[]): Express.Application => + configureServer('mysite.com', configs, mockTypeValidator, mockLogger) + it('sends configurations when visiting /', async () => { const configs = [new ConfigBuilder().withRequestType('Some Type').build()] - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app).get('/').expect(200).expect('Content-Type', /json/).expect(configs) }) @@ -27,10 +35,9 @@ describe('server', () => { it.each(methodCases)('handles a basic request with method: %s', async (verb, method) => { const endpoint = '/api/resource' - const configs = [new ConfigBuilder().withEndpoint(endpoint).withMethod(verb).build()] - const app = configureServer('example.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app) [method](endpoint) @@ -41,10 +48,9 @@ describe('server', () => { it('handles a basic request with method: HEAD', async () => { const endpoint = '/api/resource' - const configs = [new ConfigBuilder().withEndpoint(endpoint).withMethod('HEAD').build()] - const app = configureServer('example.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app).head(endpoint).expect(200) }) @@ -57,7 +63,7 @@ describe('server', () => { it.each(getCases)('serves routes matching the configured path %s', async (endpoint, pathToVisit) => { const configs = [new ConfigBuilder().withEndpoint(endpoint).withMethod('GET').build()] - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app) .get(pathToVisit) @@ -69,7 +75,7 @@ describe('server', () => { it('returns a 404 when the requested endpoint could not be found', async () => { const configs = [new ConfigBuilder().withEndpoint('/almost/correct').build()] - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app) .get('/nearly/correct') @@ -80,12 +86,11 @@ describe('server', () => { it('logs successful requests', async () => { const configs = [new ConfigBuilder().withEndpoint('/api/resource').withResponseBody(undefined).build()] - const app = configureServer('example.com', configs) + const app = getApp(configs) await request(app).get('/api/resource?what=up').expect(200) - const mockedLogger = mocked(serverLogger.info) - expect(mockedLogger).toBeCalled() - expect(mockedLogger.mock.calls[1][0]).toMatchObject({ + expect(mockLogger.info).toBeCalled() + expect(mockLogger.info.mock.calls[0][0]).toMatchObject({ name: configs[0].name, request: { method: 'GET', @@ -111,7 +116,7 @@ describe('server', () => { .build(), ] - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app) .get(configs[0].request.endpoint) @@ -126,7 +131,7 @@ describe('server', () => { new ConfigBuilder().withEndpoint('/api/resource?greetings=hello&greetings=bye').build(), ] - const app = configureServer('example.com', configs) + const app = getApp(configs) await request(app).get('/api/resource?greetings=bye&greetings=hello').expect(200) }) @@ -146,7 +151,7 @@ describe('server', () => { .build(), ] - const app = configureServer('example.com', configs) + const app = getApp(configs) await request(app).get('/api/resource?greetings=hi&greetings=bye').expect(202).expect('YES') }) @@ -156,7 +161,7 @@ describe('server', () => { new ConfigBuilder().withEndpoint('/api/resource?greetings=hello&greetings=bye').build(), ] - const app = configureServer('example.com', configs) + const app = getApp(configs) await request(app).get('/api/resource?greetings=yellow&greetings=bye').expect(404) }) @@ -175,7 +180,7 @@ describe('server', () => { ] mockTypeValidator.validate.mockResolvedValue({ success: true }) - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app).post(configs[0].request.endpoint).send('Yo dude!').expect(404).expect('Noice') }) @@ -186,7 +191,7 @@ describe('server', () => { ] mockTypeValidator.validate.mockResolvedValue({ success: false, errors: ['oops'] }) - const app = configureServer('mysite.com', configs, mockTypeValidator) + const app = getApp(configs) await request(app) .post(configs[0].request.endpoint)