diff --git a/__tests__/server/__snapshots__/shutdown.spec.js.snap b/__tests__/server/__snapshots__/shutdown.spec.js.snap index 994b03f28..03be81ce9 100644 --- a/__tests__/server/__snapshots__/shutdown.spec.js.snap +++ b/__tests__/server/__snapshots__/shutdown.spec.js.snap @@ -4,12 +4,8 @@ exports[`shutdown SIGINT forcibly exits if still running later on 1`] = `10000`; exports[`shutdown SIGINT writes an error message if still running later on 1`] = ` [ - [ - "still running after 10s, forcibly shutting down", - ], - [ - "shutting down, forcibly stopping node", - ], + "still running after 10s, forcibly shutting down", + "shutting down, forcibly stopping node", ] `; @@ -25,12 +21,8 @@ exports[`shutdown SIGTERM forcibly exits if still running later on 1`] = `10000` exports[`shutdown SIGTERM writes an error message if still running later on 1`] = ` [ - [ - "still running after 10s, forcibly shutting down", - ], - [ - "shutting down, forcibly stopping node", - ], + "still running after 10s, forcibly shutting down", + "shutting down, forcibly stopping node", ] `; diff --git a/__tests__/server/config/env/__snapshots__/argv.spec.js.snap b/__tests__/server/config/env/__snapshots__/argv.spec.js.snap index 1d870c68d..412e483ca 100644 --- a/__tests__/server/config/env/__snapshots__/argv.spec.js.snap +++ b/__tests__/server/config/env/__snapshots__/argv.spec.js.snap @@ -67,6 +67,7 @@ exports[`argv config has development options and defaults 6`] = ` "warn", "log", "info", + "trace", ], "default": "log", "describe": "Lowest level of log entries to show", @@ -111,6 +112,7 @@ exports[`argv config has production options and defaults 2`] = ` "warn", "log", "info", + "trace", ], "default": "info", "describe": "Lowest level of log entries to show", diff --git a/__tests__/server/index.spec.js b/__tests__/server/index.spec.js index 2470dd3ed..bbfc256a7 100644 --- a/__tests__/server/index.spec.js +++ b/__tests__/server/index.spec.js @@ -15,6 +15,7 @@ * permissions and limitations under the License. */ +import util from 'util'; import fs from 'fs'; import path from 'path'; @@ -359,14 +360,16 @@ describe('server index', () => { await load({ ssrServerError: true }); expect(console.error).toHaveBeenCalled(); - expect(console.error.mock.calls[0][0]).toMatchSnapshot(); + console.error.mock.calls[0].pop(); + expect(util.format(...console.error.mock.calls[0])).toMatchSnapshot(); }); it('logs errors when listening on the metrics server fails', async () => { await load({ metricsServerError: true }); expect(console.error).toHaveBeenCalled(); - expect(console.error.mock.calls[0][0]).toMatchSnapshot(); + console.error.mock.calls[0].pop(); + expect(util.format(...console.error.mock.calls[0])).toMatchSnapshot(); }); it('closes servers when starting ssrServer fails', async () => { @@ -383,7 +386,7 @@ describe('server index', () => { await load(); expect(console.log).toHaveBeenCalled(); - expect(console.log.mock.calls[1][0]).toMatch('🌎 One App server listening on port 3000'); + expect(util.format(...console.log.mock.calls[1])).toMatch('🌎 One App server listening on port 3000'); }); it('logs when metrics server is successfully listening on the port', async () => { @@ -393,7 +396,7 @@ describe('server index', () => { await load(); expect(console.log).toHaveBeenCalled(); - expect(console.log.mock.calls[0][0]).toMatch('📊 Metrics server listening on port 3005'); + expect(util.format(...console.log.mock.calls[0])).toMatch('📊 Metrics server listening on port 3005'); }); it('initiates module-map polling if successfully listening on port', async () => { diff --git a/__tests__/server/metricsServer.spec.js b/__tests__/server/metricsServer.spec.js index 2847491e6..2c7423e05 100644 --- a/__tests__/server/metricsServer.spec.js +++ b/__tests__/server/metricsServer.spec.js @@ -14,6 +14,8 @@ * permissions and limitations under the License. */ +jest.mock('pino'); + describe('metricsServer', () => { jest.mock('../../src/server/metrics/intl-cache', () => ({ cacheSizeCollector: 'cacheSizeCollector', diff --git a/__tests__/server/plugins/reactHtml/createRequestHtmlFragment.spec.jsx b/__tests__/server/plugins/reactHtml/createRequestHtmlFragment.spec.jsx index 7248fceca..19215e544 100644 --- a/__tests__/server/plugins/reactHtml/createRequestHtmlFragment.spec.jsx +++ b/__tests__/server/plugins/reactHtml/createRequestHtmlFragment.spec.jsx @@ -25,6 +25,8 @@ import { isRedirectUrlAllowed } from '../../../../src/server/utils/redirectAllow import * as reactRendering from '../../../../src/server/utils/reactRendering'; +jest.spyOn(console, 'error').mockImplementation(() => 0); + jest.mock('../../../../src/server/plugins/reactHtml/staticErrorPage', () => jest.fn()); jest.mock('../../../../src/server/utils/redirectAllowList', () => ({ isRedirectUrlAllowed: jest.fn(() => true), @@ -53,8 +55,6 @@ const renderForStringSpy = jest.spyOn(reactRendering, 'renderForString'); const renderForStaticMarkupSpy = jest.spyOn(reactRendering, 'renderForStaticMarkup'); describe('createRequestHtmlFragment', () => { - jest.spyOn(console, 'error').mockImplementation(() => {}); - let req; let res; let createRoutes; @@ -81,6 +81,7 @@ describe('createRequestHtmlFragment', () => { beforeEach(() => { jest.clearAllMocks(); req = jest.fn(); + req.log = { error: jest.fn() }; req.headers = {}; res = jest.fn(); @@ -96,7 +97,7 @@ describe('createRequestHtmlFragment', () => { renderForStringSpy.mockClear(); renderForStaticMarkupSpy.mockClear(); - console.error.mockClear(); + req.log.error.mockClear(); }); const requireCreateRequestHtmlFragment = (...args) => require( @@ -161,7 +162,7 @@ describe('createRequestHtmlFragment', () => { await requireCreateRequestHtmlFragment(req, res, { createRoutes }); - expect(console.error).toHaveBeenCalledWith('error creating request HTML fragment for http://example.com/request', expect.any(Error)); + expect(req.log.error).toHaveBeenCalledWith('error creating request HTML fragment for %s', 'http://example.com/request', expect.any(Error)); expect(res.code).toHaveBeenCalledWith(404); expect(createRoutes).toHaveBeenCalledWith(req.store); expect(req.appHtml).toBe(undefined); @@ -208,8 +209,8 @@ describe('createRequestHtmlFragment', () => { await requireCreateRequestHtmlFragment(req, res, { createRoutes: brokenCreateRoutes }); - expect(console.error).toHaveBeenCalled(); - expect(console.error.mock.calls[0]).toEqual(['error creating request HTML fragment for http://example.com/request', createRoutesError]); + expect(req.log.error).toHaveBeenCalled(); + expect(req.log.error.mock.calls[0]).toEqual(['error creating request HTML fragment for %s', 'http://example.com/request', createRoutesError]); }); it('should use a circuit breaker', async () => { diff --git a/__tests__/server/plugins/reactHtml/createRequestStore.spec.js b/__tests__/server/plugins/reactHtml/createRequestStore.spec.js index 5d857c741..26e50e71c 100644 --- a/__tests__/server/plugins/reactHtml/createRequestStore.spec.js +++ b/__tests__/server/plugins/reactHtml/createRequestStore.spec.js @@ -54,9 +54,6 @@ holocron.getModuleMap.mockImplementation(() => fromJS({ setClientModuleMapCache(holocron.getModuleMap().toJS()); describe('createRequestStore', () => { - jest.spyOn(console, 'log').mockImplementation(() => {}); - jest.spyOn(console, 'error').mockImplementation(() => {}); - let request; let reply; let reducers; @@ -81,6 +78,7 @@ describe('createRequestStore', () => { url: '/', raw: {}, method: 'get', + log: { error: jest.fn() }, }; reply = { @@ -99,7 +97,7 @@ describe('createRequestStore', () => { it('should add a store to the request object', () => { createRequestStore(request, reply, { reducers }); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(request.store).toBeTruthy(); }); @@ -112,7 +110,7 @@ describe('createRequestStore', () => { it('should send the static error page when there is an error', () => { createRequestStore(request, reply, { reducers: null }); - expect(console.error).toHaveBeenCalled(); + expect(request.log.error).toHaveBeenCalled(); expect(renderStaticErrorPage).toHaveBeenCalledWith(request, reply); }); diff --git a/__tests__/server/plugins/reactHtml/index.spec.jsx b/__tests__/server/plugins/reactHtml/index.spec.jsx index 88a6a72b5..e35675577 100644 --- a/__tests__/server/plugins/reactHtml/index.spec.jsx +++ b/__tests__/server/plugins/reactHtml/index.spec.jsx @@ -14,6 +14,7 @@ * permissions and limitations under the License. */ +import util from 'util'; import Fastify from 'fastify'; import { fromJS } from 'immutable'; import reactHtml, { @@ -34,6 +35,9 @@ import createRequestHtmlFragmentHook from '../../../../src/server/plugins/reactH import conditionallyAllowCors from '../../../../src/server/plugins/conditionallyAllowCors'; import { isRedirectUrlAllowed } from '../../../../src/server/utils/redirectAllowList'; +jest.spyOn(console, 'error').mockImplementation(() => 0); +jest.spyOn(console, 'warn').mockImplementation(() => 0); + jest.mock('react-helmet'); jest.mock('../../../../src/server/utils/redirectAllowList', () => ({ @@ -141,11 +145,6 @@ jest.mock('../../../../src/server/plugins/reactHtml/createRequestStore'); jest.mock('../../../../src/server/plugins/reactHtml/createRequestHtmlFragment'); jest.mock('../../../../src/server/plugins/conditionallyAllowCors'); -jest.spyOn(console, 'info').mockImplementation(() => {}); -jest.spyOn(console, 'log').mockImplementation(() => {}); -jest.spyOn(console, 'error').mockImplementation(() => {}); -jest.spyOn(console, 'warn').mockImplementationOnce(() => {}); - global.fetch = () => Promise.resolve({ data: 'data' }); describe('reactHtml', () => { @@ -259,6 +258,10 @@ describe('reactHtml', () => { }; request.clientModuleMapCache = getClientModuleMapCache(); request.appHtml = appHtml; + request.log = { + info: jest.fn(), + error: jest.fn(), + }; reply = jest.fn(); reply.status = jest.fn(() => reply); @@ -291,7 +294,7 @@ describe('reactHtml', () => { it('sends a rendered page', () => { sendHtml(request, reply); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.send).toHaveBeenCalledTimes(1); expect(reply.send.mock.calls[0][0]).toContain(''); @@ -316,7 +319,7 @@ describe('reactHtml', () => { sendHtml(request, reply); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.send).toHaveBeenCalledTimes(1); expect(reply.send.mock.calls[0][0]).toContain(''); @@ -437,10 +440,8 @@ describe('reactHtml', () => { request.store = { getState: jest.fn(() => { throw new Error('cannot get state'); }), }; - /* eslint-disable no-console */ sendHtml(request, reply); - expect(console.error).toHaveBeenCalled(); - /* eslint-enable no-console */ + expect(request.log.error).toHaveBeenCalled(); expect(reply.send).toHaveBeenCalledTimes(1); expect(reply.send.mock.calls[0][0]).toContain(''); expect(reply.send.mock.calls[0][0]).toContain(''); @@ -449,14 +450,12 @@ describe('reactHtml', () => { it('sends the static error page when appHtml is not a string', () => { request.appHtml = [1, 2, 3]; - /* eslint-disable no-console */ sendHtml(request, reply); - expect(console.error).toHaveBeenCalled(); + expect(request.log.error).toHaveBeenCalled(); expect(reply.code).toHaveBeenCalledWith(500); expect(reply.send).toHaveBeenCalledTimes(1); expect(reply.send.mock.calls[0][0]).toContain(''); expect(removeInitialState(reply.send.mock.calls[0][0])).not.toContain('undefined'); - /* eslint-enable no-console */ }); it('sends a page with an empty div#root when appHtml is undefined', () => { @@ -605,9 +604,10 @@ describe('reactHtml', () => { send: jest.fn(() => fakeReply), code: jest.fn(() => fakeReply), header: jest.fn(() => fakeReply), + type: jest.fn(() => fakeReply), }; sendHtml(request, fakeReply); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(fakeReply.send).toHaveBeenCalledTimes(1); expect(fakeReply.header).toHaveBeenCalledWith('content-type', 'text/plain; charset=utf-8'); expect(fakeReply.send.mock.calls[0][0]).not.toContain(''); @@ -840,10 +840,8 @@ describe('reactHtml', () => { .mockImplementationOnce(() => 'serialized bare state possible'); sendHtml(request, reply); - /* eslint-disable no-console */ - expect(console.error).toHaveBeenCalledTimes(1); - expect(console.error).toHaveBeenCalledWith('encountered an error serializing full client initial state', fullStateError); - /* eslint-enable no-console */ + expect(request.log.error).toHaveBeenCalledTimes(1); + expect(request.log.error).toHaveBeenCalledWith('encountered an error serializing full client initial state', fullStateError); expect(transit.toJSON).toHaveBeenCalledTimes(3); expect(reply.send).toHaveBeenCalledTimes(1); @@ -870,11 +868,9 @@ describe('reactHtml', () => { .mockImplementationOnce(() => 'second cache clean call'); sendHtml(request, reply); - /* eslint-disable no-console */ - expect(console.error).toHaveBeenCalledTimes(3); - expect(console.error).toHaveBeenCalledWith('encountered an error serializing full client initial state', fullStateError); - expect(console.error).toHaveBeenCalledWith('unable to build the most basic initial state for a client to startup', minimalStateError); - /* eslint-enable no-console */ + expect(request.log.error).toHaveBeenCalledTimes(3); + expect(request.log.error).toHaveBeenCalledWith('encountered an error serializing full client initial state', fullStateError); + expect(request.log.error).toHaveBeenCalledWith('unable to build the most basic initial state for a client to startup', minimalStateError); expect(transit.toJSON).toHaveBeenCalledTimes(4); expect(reply.send).toHaveBeenCalledTimes(1); @@ -927,7 +923,7 @@ describe('reactHtml', () => { jest.spyOn(console, 'error'); isRedirectUrlAllowed.mockImplementationOnce(() => false); checkStateForRedirectAndStatusCode(req, reply); - expect(console.error).toHaveBeenCalledWith(`'${destination}' is not an allowed redirect URL`); + expect(util.format(...console.error.mock.calls[0])).toBe(`'${destination}' is not an allowed redirect URL`); }); }); @@ -1042,7 +1038,7 @@ describe('reactHtml', () => { await fastify.decorateReply.mock.calls[0][1].bind(reply)(request, reply); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.send).toHaveBeenCalledTimes(1); expect(reply.send.mock.calls[0][0]).toContain(''); diff --git a/__tests__/server/shutdown.spec.js b/__tests__/server/shutdown.spec.js index 16e9e2795..7c1f8bcfd 100644 --- a/__tests__/server/shutdown.spec.js +++ b/__tests__/server/shutdown.spec.js @@ -14,6 +14,8 @@ * permissions and limitations under the License. */ +import util from 'util'; + describe('shutdown', () => { jest.spyOn(global, 'setTimeout').mockImplementation(() => {}); jest.spyOn(global, 'setImmediate').mockImplementation(() => {}); @@ -114,7 +116,7 @@ describe('shutdown', () => { expect(setTimeout).toHaveBeenCalledTimes(1); setTimeout.mock.calls[0][0](); expect(console.error).toHaveBeenCalled(); - expect(console.error.mock.calls).toMatchSnapshot(); + expect(console.error.mock.calls.map((args) => util.format(...args))).toMatchSnapshot(); }); it('uses node unref to prevent the exit timeout from preventing exiting', () => { diff --git a/__tests__/server/ssrServer-requests.spec.js b/__tests__/server/ssrServer-requests.spec.js index a361acabb..e82a1833d 100644 --- a/__tests__/server/ssrServer-requests.spec.js +++ b/__tests__/server/ssrServer-requests.spec.js @@ -14,11 +14,12 @@ * permissions and limitations under the License. */ +import util from 'util'; import ssrServer from '../../src/server/ssrServer'; const { NODE_ENV } = process.env; -const warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); +jest.mock('pino'); jest.mock('fastify-metrics', () => (_req, _opts, done) => done()); describe('ssrServer route testing', () => { @@ -44,9 +45,11 @@ describe('ssrServer route testing', () => { describe('/_/report/security/csp-violation', () => { describe('production', () => { let server; + let warnSpy; beforeAll(async () => { process.env.NODE_ENV = 'production'; server = await ssrServer(); + warnSpy = jest.spyOn(server.log, 'warn'); }); test('with csp-report', async () => { @@ -62,7 +65,9 @@ describe('ssrServer route testing', () => { }, }), }); - expect(warnSpy).toHaveBeenCalledWith('CSP Violation: {"csp-report":{"document-uri":"bad.example.com"}}'); + expect(util.format(...warnSpy.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: {"csp-report":{"document-uri":"bad.example.com"}}"' + ); expect(resp.statusCode).toEqual(204); }); @@ -74,16 +79,20 @@ describe('ssrServer route testing', () => { 'Content-Type': 'application/csp-report', }, }); - expect(warnSpy).toHaveBeenCalledWith('CSP Violation: No data received!'); + expect(util.format(...warnSpy.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: No data received!"' + ); expect(resp.statusCode).toEqual(204); }); }); describe('development', () => { let server; + let warnSpy; beforeAll(async () => { process.env.NODE_ENV = 'development'; server = await ssrServer(); + warnSpy = jest.spyOn(server.log, 'warn'); }); test('with csp-report', async () => { @@ -104,7 +113,9 @@ describe('ssrServer route testing', () => { }, }), }); - expect(warnSpy).toHaveBeenCalledWith('CSP Violation: sourceFile.js:123:432 on page bad.example.com violated the script-src policy via blockedUri.example.com'); + expect(util.format(...warnSpy.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: sourceFile.js:123:432 on page bad.example.com violated the script-src policy via blockedUri.example.com"' + ); expect(resp.statusCode).toEqual(204); }); @@ -116,7 +127,9 @@ describe('ssrServer route testing', () => { 'Content-Type': 'application/csp-report', }, }); - expect(warnSpy).toHaveBeenCalledWith('CSP Violation reported, but no data received'); + expect(util.format(...warnSpy.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation reported, but no data received"' + ); expect(resp.statusCode).toEqual(204); }); }); diff --git a/__tests__/server/ssrServer.spec.js b/__tests__/server/ssrServer.spec.js index f46d99e5d..f9ee2ddd1 100644 --- a/__tests__/server/ssrServer.spec.js +++ b/__tests__/server/ssrServer.spec.js @@ -14,6 +14,7 @@ * permissions and limitations under the License. */ +import util from 'util'; import path from 'path'; import compress from '@fastify/compress'; import Fastify from 'fastify'; @@ -29,6 +30,7 @@ import setAppVersionHeader from '../../src/server/plugins/setAppVersionHeader'; import addSecurityHeadersPlugin from '../../src/server/plugins/addSecurityHeaders'; import csp from '../../src/server/plugins/csp'; import logging from '../../src/server/utils/logging/fastifyPlugin'; +import logger from '../../src/server/utils/logging/logger'; import forwardedHeaderParser from '../../src/server/plugins/forwardedHeaderParser'; import renderHtml from '../../src/server/plugins/reactHtml'; import renderStaticErrorPage from '../../src/server/plugins/reactHtml/staticErrorPage'; @@ -36,7 +38,9 @@ import addFrameOptionsHeader from '../../src/server/plugins/addFrameOptionsHeade import addCacheHeaders from '../../src/server/plugins/addCacheHeaders'; import { // eslint-disable-next-line import/named - _setConfig, serviceWorkerHandler, webManifestMiddleware, + _setConfig, + serviceWorkerHandler, + webManifestMiddleware, } from '../../src/server/pwa'; import ssrServer from '../../src/server/ssrServer'; @@ -51,11 +55,13 @@ jest.mock('@fastify/static'); jest.mock('@fastify/helmet'); jest.mock('@fastify/sensible'); jest.mock('fastify-metrics'); +jest.mock('pino'); jest.mock('../../src/server/plugins/ensureCorrelationId'); jest.mock('../../src/server/plugins/setAppVersionHeader'); jest.mock('../../src/server/plugins/addSecurityHeaders'); jest.mock('../../src/server/plugins/csp'); +jest.mock('../../src/server/utils/logging/logger'); jest.mock('../../src/server/utils/logging/fastifyPlugin'); jest.mock('../../src/server/plugins/forwardedHeaderParser'); jest.mock('../../src/server/plugins/reactHtml'); @@ -80,11 +86,6 @@ afterAll(() => { }); describe('ssrServer', () => { - jest.spyOn(console, 'info').mockImplementation(() => { }); - jest.spyOn(console, 'log').mockImplementation(() => { }); - jest.spyOn(console, 'warn').mockImplementation(() => { }); - jest.spyOn(console, 'error').mockImplementation(() => { }); - let register; let setNotFoundHandler; let setErrorHandler; @@ -117,6 +118,8 @@ describe('ssrServer', () => { expect(Fastify).toHaveBeenCalledWith({ frameworkErrors: expect.any(Function), bodyLimit: 10485760, + logger, + disableRequestLogging: true, }); expect(register).toHaveBeenCalledTimes(13); @@ -125,22 +128,22 @@ describe('ssrServer', () => { expect(register.mock.calls[2][0]).toEqual(fastifyCookie); expect(register.mock.calls[3][0]).toEqual(logging); expect(register.mock.calls[4][0]).toEqual(fastifyMetrics); - expect(register.mock.calls[5]).toEqual([compress, { - zlibOptions: { - level: 1, + expect(register.mock.calls[5]).toEqual([ + compress, + { + zlibOptions: { + level: 1, + }, + encodings: ['gzip'], }, - encodings: [ - 'gzip', - ], - }]); + ]); expect(register.mock.calls[6][0]).toEqual(fastifyFormbody); - expect(register.mock.calls[7]).toEqual([addSecurityHeadersPlugin, { - matchGetRoutes: [ - '/_/status', - '/_/pwa/service-worker.js', - '/_/pwa/manifest.webmanifest', - ], - }]); + expect(register.mock.calls[7]).toEqual([ + addSecurityHeadersPlugin, + { + matchGetRoutes: ['/_/status', '/_/pwa/service-worker.js', '/_/pwa/manifest.webmanifest'], + }, + ]); expect(register.mock.calls[8][0]).toEqual(setAppVersionHeader); expect(register.mock.calls[9][0]).toEqual(forwardedHeaderParser); expect(register.mock.calls[10][0]).toEqual(expect.any(Function)); // abstraction @@ -148,10 +151,14 @@ describe('ssrServer', () => { expect(register.mock.calls[12][0]).toEqual(expect.any(Function)); // abstraction const staticRegister = jest.fn(); - register.mock.calls[10][0]({ - register: staticRegister, - get: jest.fn(), - }, null, jest.fn()); + register.mock.calls[10][0]( + { + register: staticRegister, + get: jest.fn(), + }, + null, + jest.fn() + ); expect(staticRegister.mock.calls[0]).toEqual([ fastifyStatic, @@ -163,21 +170,29 @@ describe('ssrServer', () => { ]); const pwaRegister = jest.fn(); - register.mock.calls[11][0]({ - register: pwaRegister, - get: jest.fn(), - post: jest.fn(), - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: pwaRegister, + get: jest.fn(), + post: jest.fn(), + }, + null, + jest.fn() + ); expect(pwaRegister.mock.calls[0][0]).toEqual(addCacheHeaders); expect(pwaRegister.mock.calls[1][0]).toEqual(csp); const renderRegister = jest.fn(); - register.mock.calls[12][0]({ - register: renderRegister, - get: jest.fn(), - post: jest.fn(), - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: renderRegister, + get: jest.fn(), + post: jest.fn(), + }, + null, + jest.fn() + ); expect(renderRegister.mock.calls[0][0]).toEqual(addCacheHeaders); expect(renderRegister.mock.calls[1][0]).toEqual(csp); @@ -206,7 +221,9 @@ describe('ssrServer', () => { const { frameworkErrors } = Fastify.mock.calls[0][0]; const error = new Error('testing'); + delete error.stack; const request = { + log: { error: jest.fn() }, method: 'get', url: 'example.com', headers: {}, @@ -215,9 +232,8 @@ describe('ssrServer', () => { frameworkErrors(error, request, reply); - expect(console.error).toHaveBeenCalledWith( - 'Fastify internal error: method get, url "example.com", correlationId "undefined"', - error + expect(util.format(...request.log.error.mock.calls[0])).toMatchInlineSnapshot( + '"Fastify internal error: method get, url "example.com", correlationId "undefined" [Error: testing]"' ); expect(renderStaticErrorPage).toHaveBeenCalled(); }); @@ -228,10 +244,14 @@ describe('ssrServer', () => { const get = jest.fn(); - register.mock.calls[10][0]({ - register: jest.fn(), - get, - }, null, jest.fn()); + register.mock.calls[10][0]( + { + register: jest.fn(), + get, + }, + null, + jest.fn() + ); const reply = { status: jest.fn(() => reply), @@ -250,10 +270,14 @@ describe('ssrServer', () => { const get = jest.fn(); - register.mock.calls[10][0]({ - register: jest.fn(), - get, - }, null, jest.fn()); + register.mock.calls[10][0]( + { + register: jest.fn(), + get, + }, + null, + jest.fn() + ); const reply = { status: jest.fn(() => reply), @@ -271,11 +295,15 @@ describe('ssrServer', () => { const get = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get, - post: jest.fn(), - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get, + post: jest.fn(), + }, + null, + jest.fn() + ); const reply = { status: jest.fn(() => reply), @@ -293,13 +321,19 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); - const request = {}; + const request = { + log: { warn: jest.fn() }, + }; const reply = { status: jest.fn(() => reply), send: jest.fn(() => reply), @@ -308,7 +342,9 @@ describe('ssrServer', () => { post.mock.calls[0][1](request, reply); expect(post.mock.calls[0][0]).toEqual('/_/report/security/csp-violation'); - expect(console.warn).toHaveBeenCalledWith('CSP Violation reported, but no data received'); + expect(request.log.warn).toHaveBeenCalledWith( + 'CSP Violation reported, but no data received' + ); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -320,17 +356,22 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: { 'Content-Type': 'application/csp-report', }, body: JSON.stringify({}), + log: { warn: jest.fn() }, }; const reply = { status: jest.fn(() => reply), @@ -340,7 +381,9 @@ describe('ssrServer', () => { post.mock.calls[0][1](request, reply); expect(post.mock.calls[0][0]).toEqual('/_/report/security/csp-violation'); - expect(console.warn).toHaveBeenCalledWith('CSP Violation reported, but no data received'); + expect(request.log.warn).toHaveBeenCalledWith( + 'CSP Violation reported, but no data received' + ); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -351,11 +394,15 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { body: JSON.stringify({ @@ -368,6 +415,7 @@ describe('ssrServer', () => { 'source-file': 'source-file', }, }), + log: { warn: jest.fn() }, }; const reply = { status: jest.fn(() => reply), @@ -377,7 +425,9 @@ describe('ssrServer', () => { post.mock.calls[0][1](request, reply); expect(post.mock.calls[0][0]).toEqual('/_/report/security/csp-violation'); - expect(console.warn).toHaveBeenCalledWith('CSP Violation: source-file:line-number:column-number on page document-uri violated the violated-directive policy via blocked-uri'); + expect(util.format(...request.log.warn.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: source-file:line-number:column-number on page document-uri violated the violated-directive policy via blocked-uri"' + ); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -387,13 +437,22 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); - const request = {}; + const request = { + log: { + warn: jest.fn(), + error: jest.fn(), + }, + }; const reply = { status: jest.fn(() => reply), send: jest.fn(() => reply), @@ -402,8 +461,8 @@ describe('ssrServer', () => { post.mock.calls[1][1](request, reply); expect(post.mock.calls[1][0]).toEqual('/_/report/errors'); - expect(console.warn).not.toHaveBeenCalled(); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.warn).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -417,14 +476,19 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: {}, + log: { warn: jest.fn() }, }; const reply = { status: jest.fn(() => reply), @@ -434,7 +498,9 @@ describe('ssrServer', () => { post.mock.calls[0][1](request, reply); expect(post.mock.calls[0][0]).toEqual('/_/report/security/csp-violation'); - expect(console.warn).toHaveBeenCalledWith('CSP Violation: No data received!'); + expect(util.format(...request.log.warn.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: No data received!"' + ); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -447,17 +513,22 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: {}, body: JSON.stringify({ unit: 'testing', }), + log: { warn: jest.fn() }, }; const reply = { status: jest.fn(() => reply), @@ -467,7 +538,9 @@ describe('ssrServer', () => { post.mock.calls[0][1](request, reply); expect(post.mock.calls[0][0]).toEqual('/_/report/security/csp-violation'); - expect(console.warn).toHaveBeenCalledWith('CSP Violation: {"unit":"testing"}'); + expect(util.format(...request.log.warn.mock.calls[0])).toMatchInlineSnapshot( + '"CSP Violation: {"unit":"testing"}"' + ); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -480,16 +553,24 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: { 'content-type': 'text/plain', }, + log: { + warn: jest.fn(), + error: jest.fn(), + }, }; const reply = { status: jest.fn(() => reply), @@ -499,8 +580,8 @@ describe('ssrServer', () => { post.mock.calls[1][1](request, reply); expect(post.mock.calls[1][0]).toEqual('/_/report/errors'); - expect(console.warn).not.toHaveBeenCalled(); - expect(console.error).not.toHaveBeenCalled(); + expect(request.log.warn).not.toHaveBeenCalled(); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.status).toHaveBeenCalledWith(415); expect(reply.send).toHaveBeenCalledWith('Unsupported Media Type'); }); @@ -512,11 +593,15 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: { @@ -525,6 +610,10 @@ describe('ssrServer', () => { 'user-agent': 'userAgent', }, body: 'invalid', + log: { + warn: jest.fn(), + error: jest.fn(), + }, }; const reply = { status: jest.fn(() => reply), @@ -534,8 +623,10 @@ describe('ssrServer', () => { post.mock.calls[1][1](request, reply); expect(post.mock.calls[1][0]).toEqual('/_/report/errors'); - expect(console.warn).toHaveBeenCalledWith('dropping an error report group, wrong interface (string)'); - expect(console.error).not.toHaveBeenCalled(); + expect(util.format(...request.log.warn.mock.calls[0])).toMatchInlineSnapshot( + '"dropping an error report group, wrong interface (string)"' + ); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -547,11 +638,15 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: { @@ -559,11 +654,11 @@ describe('ssrServer', () => { 'correlation-id': 'correlationId', 'user-agent': 'userAgent', }, - body: [ - '', - false, - 'not an object', - ], + body: ['', false, 'not an object'], + log: { + warn: jest.fn(), + error: jest.fn(), + }, }; const reply = { status: jest.fn(() => reply), @@ -573,10 +668,16 @@ describe('ssrServer', () => { post.mock.calls[1][1](request, reply); expect(post.mock.calls[1][0]).toEqual('/_/report/errors'); - expect(console.warn).toHaveBeenCalledWith('dropping an error report, wrong interface (string)'); - expect(console.warn).toHaveBeenCalledWith('dropping an error report, wrong interface (boolean)'); - expect(console.warn).toHaveBeenCalledWith('dropping an error report, wrong interface (string)'); - expect(console.error).not.toHaveBeenCalled(); + expect(util.format(...request.log.warn.mock.calls[0])).toMatchInlineSnapshot( + '"dropping an error report, wrong interface (string)"' + ); + expect(util.format(...request.log.warn.mock.calls[1])).toMatchInlineSnapshot( + '"dropping an error report, wrong interface (boolean)"' + ); + expect(util.format(...request.log.warn.mock.calls[2])).toMatchInlineSnapshot( + '"dropping an error report, wrong interface (string)"' + ); + expect(request.log.error).not.toHaveBeenCalled(); expect(reply.status).toHaveBeenCalledWith(204); expect(reply.send).toHaveBeenCalled(); }); @@ -588,11 +689,15 @@ describe('ssrServer', () => { const post = jest.fn(); - register.mock.calls[11][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[11][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const request = { headers: { @@ -600,14 +705,20 @@ describe('ssrServer', () => { 'correlation-id': 'correlationId', 'user-agent': 'userAgent', }, - body: [{ - msg: 'testing', - stack: 'stack', - href: 'href', - otherData: { - testing: true, + body: [ + { + msg: 'testing', + stack: 'stack', + href: 'href', + otherData: { + testing: true, + }, }, - }], + ], + log: { + warn: jest.fn(), + error: jest.fn(), + }, }; const reply = { status: jest.fn(() => reply), @@ -617,14 +728,14 @@ describe('ssrServer', () => { post.mock.calls[1][1](request, reply); expect(post.mock.calls[1][0]).toEqual('/_/report/errors'); - expect(console.warn).not.toHaveBeenCalled(); - expect(console.error.mock.calls.length).toBe(1); - expect(console.error.mock.calls[0][0] instanceof Error).toBe(true); - expect(console.error.mock.calls[0][0].name).toBe('ClientReportedError'); - expect(console.error.mock.calls[0][0].stack).toBe('stack'); - expect(console.error.mock.calls[0][0].userAgent).toBe('userAgent'); - expect(console.error.mock.calls[0][0].uri).toBe('href'); - expect(console.error.mock.calls[0][0].metaData).toEqual({ + expect(request.log.warn).not.toHaveBeenCalled(); + expect(request.log.error.mock.calls.length).toBe(1); + expect(request.log.error.mock.calls[0][0] instanceof Error).toBe(true); + expect(request.log.error.mock.calls[0][0].name).toBe('ClientReportedError'); + expect(request.log.error.mock.calls[0][0].stack).toBe('stack'); + expect(request.log.error.mock.calls[0][0].userAgent).toBe('userAgent'); + expect(request.log.error.mock.calls[0][0].uri).toBe('href'); + expect(request.log.error.mock.calls[0][0].metaData).toEqual({ correlationId: 'correlationId', testing: true, }); @@ -642,10 +753,14 @@ describe('ssrServer', () => { await ssrServer(); const get = jest.fn(); - register.mock.calls[12][0]({ - register: jest.fn(), - get, - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: jest.fn(), + get, + }, + null, + jest.fn() + ); const reply = { sendHtml: jest.fn(() => reply), @@ -665,10 +780,14 @@ describe('ssrServer', () => { await ssrServer(); const get = jest.fn(); - register.mock.calls[12][0]({ - register: jest.fn(), - get, - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: jest.fn(), + get, + }, + null, + jest.fn() + ); const reply = { status: jest.fn(() => reply), @@ -686,10 +805,14 @@ describe('ssrServer', () => { await ssrServer(); const get = jest.fn(); - register.mock.calls[12][0]({ - register: jest.fn(), - get, - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: jest.fn(), + get, + }, + null, + jest.fn() + ); const reply = { sendHtml: jest.fn(() => reply), @@ -705,11 +828,15 @@ describe('ssrServer', () => { await ssrServer(); const post = jest.fn(); - register.mock.calls[12][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); expect(post).not.toHaveBeenCalled(); }); @@ -720,11 +847,15 @@ describe('ssrServer', () => { await ssrServer(); const post = jest.fn(); - register.mock.calls[12][0]({ - register: jest.fn(), - get: jest.fn(), - post, - }, null, jest.fn()); + register.mock.calls[12][0]( + { + register: jest.fn(), + get: jest.fn(), + post, + }, + null, + jest.fn() + ); const reply = { sendHtml: jest.fn(() => reply), @@ -763,10 +894,12 @@ describe('ssrServer', () => { await ssrServer(); const error = new Error('testing'); + delete error.stack; const request = { method: 'get', url: '/example', headers: {}, + log: { error: jest.fn() }, }; const reply = { code: jest.fn(() => reply), @@ -776,7 +909,9 @@ describe('ssrServer', () => { await setErrorHandler.mock.calls[0][0](error, request, reply); - expect(console.error).toHaveBeenCalledWith('Fastify application error: method get, url "/example", correlationId "undefined", headersSent: false', error); + expect(util.format(...request.log.error.mock.calls[0])).toMatchInlineSnapshot( + '"Fastify application error: method get, url "/example", correlationId "undefined", headersSent: false [Error: testing]"' + ); expect(renderStaticErrorPage).toHaveBeenCalledWith(request, reply); }); @@ -788,7 +923,9 @@ describe('ssrServer', () => { await ssrServer(); const error = new Error('testing'); + delete error.stack; const request = { + log: { error: jest.fn() }, method: 'get', url: '/example', headers: { @@ -805,7 +942,9 @@ describe('ssrServer', () => { await setErrorHandler.mock.calls[0][0](error, request, reply); - expect(console.error).toHaveBeenCalledWith('Fastify application error: method get, url "/example", correlationId "123", headersSent: true', error); + expect(util.format(...request.log.error.mock.calls[0])).toMatchInlineSnapshot( + '"Fastify application error: method get, url "/example", correlationId "123", headersSent: true [Error: testing]"' + ); expect(renderStaticErrorPage).toHaveBeenCalledWith(request, reply); }); }); diff --git a/__tests__/server/utils/__snapshots__/pollModuleMap.spec.js.snap b/__tests__/server/utils/__snapshots__/pollModuleMap.spec.js.snap index 3154b586b..63bed56b3 100644 --- a/__tests__/server/utils/__snapshots__/pollModuleMap.spec.js.snap +++ b/__tests__/server/utils/__snapshots__/pollModuleMap.spec.js.snap @@ -6,26 +6,10 @@ exports[`pollModuleMap polling monitor logs when polling is considered stopped 1 ] `; -exports[`pollModuleMap polling monitor logs when polling is considered stopped 2`] = ` -[ - "pollModuleMap: polling has unexpectedly stopped. Last poll: 11000ms ago, Max poll: 10000ms.", -] -`; +exports[`pollModuleMap polling monitor logs when polling is considered stopped 2`] = `"pollModuleMap: polling has unexpectedly stopped. Last poll: 11000ms ago, Max poll: 10000ms."`; -exports[`pollModuleMap polling monitor logs when polling is considered stopped 3`] = ` -[ - "pollModuleMap: restarted polling", -] -`; +exports[`pollModuleMap polling monitor logs when polling is considered stopped 3`] = `"pollModuleMap: restarted polling"`; -exports[`pollModuleMap polling monitor logs when polling is not considered stopped 1`] = ` -[ - "pollModuleMap: running polling monitor", -] -`; +exports[`pollModuleMap polling monitor logs when polling is not considered stopped 1`] = `"pollModuleMap: running polling monitor"`; -exports[`pollModuleMap polling monitor logs when polling is not considered stopped 2`] = ` -[ - "pollModuleMap: polling is working as expected. Last poll: 2000ms ago, Max poll: 10000ms.", -] -`; +exports[`pollModuleMap polling monitor logs when polling is not considered stopped 2`] = `"pollModuleMap: polling is working as expected. Last poll: 2000ms ago, Max poll: 10000ms."`; diff --git a/__tests__/server/utils/createCircuitBreaker.spec.js b/__tests__/server/utils/createCircuitBreaker.spec.js index 17906a477..aed6d0b3c 100644 --- a/__tests__/server/utils/createCircuitBreaker.spec.js +++ b/__tests__/server/utils/createCircuitBreaker.spec.js @@ -14,6 +14,7 @@ * permissions and limitations under the License. */ +import util from 'util'; import CircuitBreaker from 'opossum'; import { getModule } from 'holocron'; import createCircuitBreaker, { @@ -141,37 +142,27 @@ describe('Circuit breaker', () => { setEventLoopDelayThreshold(-1); jest.advanceTimersByTime(5e3 + 10); await mockCircuitBreaker.fire('hola, mundo'); - expect(consoleErrorSpy.mock.calls).toMatchInlineSnapshot(` + expect(consoleErrorSpy.mock.calls[0]).toMatchInlineSnapshot(` [ - [ - [Error: Opening circuit, p(100) event loop delay (0ms) is > eventLoopDelayThreshold (-1ms)], - ], + [Error: Opening circuit, p(100) event loop delay (0ms) is > eventLoopDelayThreshold (-1ms)], ] `); }); it('should log when the circuit opens', () => { mockCircuitBreaker.open(); - expect(consoleLogSpy.mock.calls).toMatchInlineSnapshot(` - [ - [ - "Circuit breaker [mockConstructor] opened", - ], - ] - `); + expect(util.format(...consoleLogSpy.mock.calls[0])).toMatchInlineSnapshot( + '"Circuit breaker [mockConstructor] opened"' + ); }); it('should log when the circuit closes', () => { mockCircuitBreaker.open(); jest.clearAllMocks(); mockCircuitBreaker.close(); - expect(consoleLogSpy.mock.calls).toMatchInlineSnapshot(` - [ - [ - "Circuit breaker [mockConstructor] closed", - ], - ] - `); + expect(util.format(...consoleLogSpy.mock.calls[0])).toMatchInlineSnapshot( + '"Circuit breaker [mockConstructor] closed"' + ); }); describe('event loop delay threshold', () => { @@ -205,7 +196,7 @@ describe('Circuit breaker', () => { it('should warn and set value to 100 if input is not a number', () => { setEventLoopDelayPercentile('hello, world'); - expect(consoleWarnSpy.mock.calls[0][0]).toMatchInlineSnapshot( + expect(util.format(...consoleWarnSpy.mock.calls[0])).toMatchInlineSnapshot( '"Event loop percentile must be an integer in range 1-100; given "hello, world". Defaulting to p(100)."' ); expect(getEventLoopDelayPercentile()).toBe(100); @@ -213,7 +204,7 @@ describe('Circuit breaker', () => { it('should warn and set value to 100 if input less than 1', () => { setEventLoopDelayPercentile(0); - expect(consoleWarnSpy.mock.calls[0][0]).toMatchInlineSnapshot( + expect(util.format(...consoleWarnSpy.mock.calls[0])).toMatchInlineSnapshot( '"Event loop percentile must be an integer in range 1-100; given 0. Defaulting to p(100)."' ); expect(getEventLoopDelayPercentile()).toBe(100); @@ -221,7 +212,7 @@ describe('Circuit breaker', () => { it('should warn and set value to 100 if input less grater than 100', () => { setEventLoopDelayPercentile(101); - expect(consoleWarnSpy.mock.calls[0][0]).toMatchInlineSnapshot( + expect(util.format(...consoleWarnSpy.mock.calls[0])).toMatchInlineSnapshot( '"Event loop percentile must be an integer in range 1-100; given 101. Defaulting to p(100)."' ); expect(getEventLoopDelayPercentile()).toBe(100); @@ -229,7 +220,7 @@ describe('Circuit breaker', () => { it('should warn and set value to 100 if input is a float', () => { setEventLoopDelayPercentile(99.9); - expect(consoleWarnSpy.mock.calls[0][0]).toMatchInlineSnapshot( + expect(util.format(...consoleWarnSpy.mock.calls[0])).toMatchInlineSnapshot( '"Event loop percentile must be an integer in range 1-100; given 99.9. Defaulting to p(100)."' ); expect(getEventLoopDelayPercentile()).toBe(100); diff --git a/__tests__/server/utils/devCdnFactory.spec.js b/__tests__/server/utils/devCdnFactory.spec.js index 7094b7f9d..b47a14070 100644 --- a/__tests__/server/utils/devCdnFactory.spec.js +++ b/__tests__/server/utils/devCdnFactory.spec.js @@ -13,6 +13,7 @@ */ /* eslint-disable no-console -- console used in tests */ +import util from 'util'; import fetch from 'node-fetch'; import fs from 'fs'; import rimraf from 'rimraf'; @@ -22,6 +23,7 @@ import ProxyAgent from 'proxy-agent'; import oneAppDevCdn from '../../../src/server/utils/devCdnFactory'; jest.mock('node-fetch'); +jest.mock('pino'); const pathToStubs = path.join(__dirname, 'stubs'); const pathToCache = path.join(__dirname, '..', '.cache'); @@ -458,8 +460,8 @@ describe('one-app-dev-cdn', () => { expect(response.body).toEqual(JSON.stringify(defaultLocalMap)); expect(fetch.mock.calls[0]).toContain(remoteModuleMapUrl); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.warn).toHaveBeenCalledWith( - 'one-app-dev-cdn error loading module map from https://my-domain.com/map/module-map.json: Error: simulated timeout or some other network error!' + expect(util.format(...console.warn.mock.calls[0])).toMatch( + /one-app-dev-cdn error loading module map from https:\/\/my-domain.com\/map\/module-map.json: Error: simulated timeout or some other network error!/ ); }); }); @@ -479,8 +481,8 @@ describe('one-app-dev-cdn', () => { expect(response.body).toEqual(JSON.stringify(defaultLocalMap)); expect(fetch.mock.calls[0]).toContain(remoteModuleMapUrl); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.warn).toHaveBeenCalledWith( - 'one-app-dev-cdn error loading module map from https://my-domain.com/map/module-map.json: TypeError: Cannot convert undefined or null to object' + expect(util.format(...console.warn.mock.calls[0])).toMatch( + /one-app-dev-cdn error loading module map from https:\/\/my-domain.com\/map\/module-map.json: TypeError: Cannot convert undefined or null to object/ ); }); }); diff --git a/__tests__/server/utils/heapdump.spec.js b/__tests__/server/utils/heapdump.spec.js index 1d14dfa61..c57e75424 100644 --- a/__tests__/server/utils/heapdump.spec.js +++ b/__tests__/server/utils/heapdump.spec.js @@ -14,6 +14,8 @@ * permissions and limitations under the License. */ +import util from 'util'; + const sleep = (ms) => new Promise((res) => setTimeout(res, ms)); describe('heapdump', () => { @@ -114,7 +116,7 @@ describe('heapdump', () => { console.warn.mockClear(); process.on.mock.calls[0][1](); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.warn.mock.calls[0][0]).toBe(`about to write a heapdump to /tmp/heapdump-${pid}-1525145998246.heapsnapshot`); + expect(util.format(...console.warn.mock.calls[0])).toBe(`about to write a heapdump to /tmp/heapdump-${pid}-1525145998246.heapsnapshot`); await waitForStreamToFinish(fs.createWriteStream.mock.results[0].value); await sleep(20); // also wait for the callback to run }); @@ -193,7 +195,7 @@ describe('heapdump', () => { await sleep(20); // also wait for the callback to run expect(console.error).not.toHaveBeenCalled(); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.warn.mock.calls[0][0]).toBe(`wrote heapdump out to /tmp/heapdump-${pid}-1525145998246.heapsnapshot`); + expect(util.format(...console.warn.mock.calls[0])).toBe(`wrote heapdump out to /tmp/heapdump-${pid}-1525145998246.heapsnapshot`); }); }); }); diff --git a/__tests__/server/utils/logging/__snapshots__/production-formatter.spec.js.snap b/__tests__/server/utils/logging/__snapshots__/production-formatter.spec.js.snap deleted file mode 100644 index 14c86e445..000000000 --- a/__tests__/server/utils/logging/__snapshots__/production-formatter.spec.js.snap +++ /dev/null @@ -1,247 +0,0 @@ -// Jest Snapshot v1, https://goo.gl/fbAQLP - -exports[`production-formatter encodes as parseable JSON 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Darwin x64", - "id": "host-123:1234", - }, - "level": "error", - "message": "1 2 3", - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; - -exports[`production-formatter errors encodes ClientReportedError Error as parseable JSON 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Browser/5.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)", - }, - "error": { - "message": "something broke", - "name": "ClientReportedError", - "stacktrace": "Error: something broke - at methodA (resource-a.js:1:1) - at methodB (resource-b.js:1:1) -", - }, - "level": "error", - "request": { - "address": { - "uri": "https://example.com/page-the/error/occurred-on", - }, - "metaData": { - "code": "500", - "collectionMethod": "applicationError", - "correlationId": "123abc", - "moduleID": "healthy-frank", - }, - }, - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; - -exports[`production-formatter errors encodes Server Reported Error as parseable JSON with nested metadata objects 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Darwin x64", - "id": "host-123:1234", - }, - "error": { - "message": "something broke", - "name": "Error", - "stacktrace": "Error: something broke - at methodA (resource-a.js:1:1) - at methodB (resource-b.js:1:1) -", - }, - "level": "error", - "metaData": { - "moduleID": "healthy-frank", - "nestedObject": { - "level1": { - "level2": { - "level3": { - "level4": "logs nested objects correctly", - }, - }, - }, - }, - }, - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; - -exports[`production-formatter errors encodes as parseable JSON 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Darwin x64", - "id": "host-123:1234", - }, - "error": { - "message": "test error", - "name": "Error", - "stacktrace": "Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)", - }, - "level": "error", - "message": "unable to do the thing", - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; - -exports[`production-formatter errors puts a lone error in the error field 1`] = ` -{ - "message": "test error", - "name": "Error", - "stacktrace": "Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)", -} -`; - -exports[`production-formatter errors puts an error paired with a message in the error field 1`] = ` -{ - "message": "test error", - "name": "Error", - "stacktrace": "Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)", -} -`; - -exports[`production-formatter errors puts an error with other arguments in the error field and uses only the other args for the message 1`] = ` -{ - "message": "test error", - "name": "Error", - "stacktrace": "Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)", -} -`; - -exports[`production-formatter errors uses the error in the message when the error is paired with a message and other arguments 1`] = ` -{ - "message": "test error", - "name": "Error", - "stacktrace": "Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)", -} -`; - -exports[`production-formatter errors uses the error in the message when the error is paired with a message and other arguments 2`] = ` -"unable to do the thing Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7) 12 times" -`; - -exports[`production-formatter types encodes request as parseable JSON 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Darwin x64", - "id": "host-123:1234", - }, - "level": "error", - "request": { - "address": { - "url": "https://example.org/server", - }, - "direction": "in", - "metaData": { - "correlationId": "123", - "host": "example.org", - "method": "GET", - "referrer": "https://example.org/other-page", - "userAgent": "Browser/8.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)", - }, - "protocol": "https", - "statusCode": 200, - "statusText": "OK", - "timings": { - "duration": 10, - "ttfb": 20, - }, - }, - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; - -exports[`production-formatter types uses the default util.format when given an unknown type 1`] = ` -{ - "application": { - "name": "One App", - "version": "1.2.3-abc123", - }, - "device": { - "agent": "Darwin x64", - "id": "host-123:1234", - }, - "level": "error", - "message": "{ type: 'yolo' }", - "schemaVersion": "0.3.0", - "timestamp": "2018-03-02T02:39:32.948Z", -} -`; diff --git a/__tests__/server/utils/logging/__snapshots__/setup.spec.js.snap b/__tests__/server/utils/logging/__snapshots__/setup.spec.js.snap index 32e97f517..dd1559d36 100644 --- a/__tests__/server/utils/logging/__snapshots__/setup.spec.js.snap +++ b/__tests__/server/utils/logging/__snapshots__/setup.spec.js.snap @@ -19,7 +19,6 @@ exports[`setup logging outgoing requests is level info 1`] = ` "duration": 12, }, }, - "type": "request", }, ] `; diff --git a/__tests__/server/utils/logging/development-formatters/__snapshots__/utils.spec.js.snap b/__tests__/server/utils/logging/__snapshots__/utils.spec.js.snap similarity index 100% rename from __tests__/server/utils/logging/development-formatters/__snapshots__/utils.spec.js.snap rename to __tests__/server/utils/logging/__snapshots__/utils.spec.js.snap diff --git a/__tests__/server/utils/logging/config/development.spec.js b/__tests__/server/utils/logging/config/development.spec.js new file mode 100644 index 000000000..4f8f1b9c1 --- /dev/null +++ b/__tests__/server/utils/logging/config/development.spec.js @@ -0,0 +1,183 @@ +/* + * Copyright 2023 American Express Travel Related Services Company, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ + +import { PassThrough } from 'stream'; +import pinoPretty from 'pino-pretty'; +import pino from 'pino'; +import { pinoPrettyOptions } from '../../../../../src/server/utils/logging/config/development'; +import baseConfig from '../../../../../src/server/utils/logging/config/base'; + +jest.mock('yargs', () => ({ + argv: { + logLevel: 'trace', + }, +})); + +let streamData = ''; +const mockStream = new PassThrough(); +mockStream.on('data', (d) => { + streamData += d; +}); +const resetStreamData = () => { + streamData = ''; +}; + +const pinoPrettyStream = pinoPretty({ + ...pinoPrettyOptions, + destination: mockStream, + colorize: false, +}); +const logger = pino(baseConfig, pinoPrettyStream); + +describe('development logger', () => { + beforeEach(() => resetStreamData()); + afterAll(() => mockStream.destroy()); + + it('should not include pid, hostname or time', () => { + logger.log('this is a test'); + expect(streamData).toMatchInlineSnapshot(` + "LOG: this is a test + " + `); + }); + + it('should set different colors for each level', () => { + const loggerWithColor = pino( + baseConfig, + pinoPretty({ + ...pinoPrettyOptions, + destination: mockStream, + }) + ); + loggerWithColor.trace(); + loggerWithColor.debug(); + loggerWithColor.info(); + loggerWithColor.log(); + loggerWithColor.warn(); + loggerWithColor.error(); + loggerWithColor.fatal(); + expect(streamData).toMatchInlineSnapshot(` + "TRACE: + DEBUG: + INFO: + LOG: + WARN: + ERROR: + FATAL: + " + `); + }); + + it('pretty-prints an incoming request', () => { + const entry = { + type: 'request', + request: { + direction: 'in', + protocol: 'https', + address: { + uri: 'https://example.com/resource', + }, + metaData: { + method: 'GET', + correlationId: '123', + host: 'example.com', + referrer: 'https://example.com/other-resource', + userAgent: 'Browser/8.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)', + location: undefined, + }, + timings: { + duration: 13, + ttfb: 12, + }, + statusCode: 200, + statusText: 'OK', + }, + }; + logger.info(entry); + expect(streamData).toMatchInlineSnapshot(` + "INFO: 🌍 ➡ 💻 200 OK GET https://example.com/resource 12/13ms + " + `); + }); + + it('pretty-prints an outgoing request', () => { + const entry = { + type: 'request', + request: { + direction: 'out', + protocol: 'https', + address: { + uri: 'https://example.com/resource', + }, + metaData: { + method: 'GET', + correlationId: '123', + }, + timings: { + duration: 13, + }, + statusCode: 200, + statusText: 'OK', + }, + }; + logger.info(entry); + expect(streamData).toMatchInlineSnapshot(` + "INFO: 💻 ➡ 🗄️ 200 OK GET https://example.com/resource 13ms + " + `); + }); + + describe('logMethod hook', () => { + const mockError = new Error('mockError'); + delete mockError.stack; + + it('should take an error from the end of a log call and put it in the error key', () => { + logger.error('This is a %s', 'test', mockError); + expect(streamData).toMatchInlineSnapshot(` + "ERROR: This is a test + error: { + "type": "Error", + "message": "mockError", + "stack": + + } + " + `); + }); + + it('should take an error from the beginning of a log call and put it in the error key', () => { + logger.warn(mockError, 'This is another %s', 'test'); + expect(streamData).toMatchInlineSnapshot(` + "WARN: This is another test + error: { + "type": "Error", + "message": "mockError", + "stack": + + } + " + `); + }); + + it('should not change log calls that do not begin or end with errors', () => { + logger.info('This is a third %s', 'test'); + expect(streamData).toMatchInlineSnapshot(` + "INFO: This is a third test + " + `); + }); + }); +}); diff --git a/__tests__/server/utils/logging/config/production.spec.js b/__tests__/server/utils/logging/config/production.spec.js new file mode 100644 index 000000000..9bd7416d0 --- /dev/null +++ b/__tests__/server/utils/logging/config/production.spec.js @@ -0,0 +1,388 @@ +/* + * Copyright 2023 American Express Travel Related Services Company, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ + +import { PassThrough } from 'stream'; +import deepmerge from 'deepmerge'; +import pino from 'pino'; +import baseConfig from '../../../../../src/server/utils/logging/config/base'; + +jest.mock('yargs', () => ({ + argv: { + logLevel: 'trace', + }, +})); + +jest.mock('os', () => ({ + hostname: () => 'mockHostname', + type: () => 'mockType', + arch: () => 'mockArch', +})); + +jest.mock('../../../../../src/server/utils/readJsonFile', () => () => ({ + buildVersion: '1.2.3-abc123', +})); + +jest.spyOn(Date, 'now').mockReturnValue(1691618794070); + +let streamData = ''; +const mockStream = new PassThrough(); +mockStream.on('data', (d) => { + streamData += d; +}); +const resetStreamData = () => { + streamData = ''; +}; +const readLog = () => { + const entry = JSON.parse(streamData); + resetStreamData(); + return entry; +}; + +describe('production logger', () => { + let productionConfig; + let pinoConfig; + let logger; + + beforeAll(() => { + Object.defineProperty(process, 'pid', { + writable: true, + value: 1234, + }); + productionConfig = require('../../../../../src/server/utils/logging/config/production').default; + pinoConfig = deepmerge(baseConfig, productionConfig); + logger = pino(pinoConfig, mockStream); + }); + + beforeEach(() => resetStreamData()); + afterAll(() => mockStream.destroy()); + + it('should add the expected base data', () => { + logger.log('hello, word'); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "level": "notice", + "message": "hello, word", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('should serialize an error', () => { + const error = new Error('mock error'); + error.stack = 'mock stack'; + logger.error(error); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "mock error", + "name": "Error", + "stacktrace": "mock stack", + }, + "level": "error", + "message": "mock error", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('should serialize an error with a missing message and stacktrace', () => { + const error = new Error(); + delete error.stack; + logger.error(error); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "", + "name": "Error", + "stacktrace": "", + }, + "level": "error", + "message": "", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('should map the log level to the schema level', () => { + logger.error(); + expect(readLog().level).toBe('error'); + logger.warn(); + expect(readLog().level).toBe('warning'); + logger.log(); + expect(readLog().level).toBe('notice'); + logger.info(); + expect(readLog().level).toBe('info'); + logger.debug(); + expect(readLog().level).toBe('debug'); + logger.trace(); + expect(readLog().level).toBe('trace'); + }); + + describe('logMethod hook', () => { + const mockError = new Error('mockError'); + delete mockError.stack; + + it('should take an error from the end of a log call and put it in the error key', () => { + logger.error('This is a %s', 'test', mockError); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "mockError", + "name": "Error", + "stacktrace": "", + }, + "level": "error", + "message": "This is a test", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('should take an error from the beginning of a log call and put it in the error key', () => { + logger.warn(mockError, 'This is another %s', 'test'); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "mockError", + "name": "Error", + "stacktrace": "", + }, + "level": "warning", + "message": "This is another test", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('should not change log calls that do not begin or end with errors', () => { + logger.info('This is a third %s', 'test'); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "level": "info", + "message": "This is a third test", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + }); + + describe('log formatter', () => { + it('encodes ClientReportedError Error', () => { + function buildClientErrorEntry() { + const error = new Error('something broke'); + Object.assign(error, { + name: 'ClientReportedError', + stack: + 'Error: something broke\n at methodA (resource-a.js:1:1)\n at methodB (resource-b.js:1:1)\n', + userAgent: 'Browser/5.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)', + uri: 'https://example.com/page-the/error/occurred-on', + metaData: { + moduleID: 'healthy-frank', + code: '500', + collectionMethod: 'applicationError', + correlationId: '123abc', + }, + }); + return { error }; + } + logger.warn(buildClientErrorEntry()); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "Browser/5.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)", + }, + "error": { + "message": "something broke", + "name": "ClientReportedError", + "stacktrace": "Error: something broke + at methodA (resource-a.js:1:1) + at methodB (resource-b.js:1:1) + ", + }, + "level": "warning", + "message": "something broke", + "request": { + "address": { + "uri": "https://example.com/page-the/error/occurred-on", + }, + "metaData": { + "code": "500", + "collectionMethod": "applicationError", + "correlationId": "123abc", + "moduleID": "healthy-frank", + }, + }, + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('encodes Server Reported Error without metadata', () => { + function buildServerSideErrorEntry() { + const error = new Error('something broke'); + Object.assign(error, { + stack: + 'Error: something broke\n at methodA (resource-a.js:1:1)\n at methodB (resource-b.js:1:1)\n', + }); + return { error }; + } + logger.error(buildServerSideErrorEntry()); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "something broke", + "name": "Error", + "stacktrace": "Error: something broke + at methodA (resource-a.js:1:1) + at methodB (resource-b.js:1:1) + ", + }, + "level": "error", + "message": "something broke", + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + + it('encodes Server Reported Error with nested metadata objects', () => { + function buildServerSideErrorEntry() { + const error = new Error('something broke'); + Object.assign(error, { + stack: + 'Error: something broke\n at methodA (resource-a.js:1:1)\n at methodB (resource-b.js:1:1)\n', + metaData: { + moduleID: 'healthy-frank', + nestedObject: { + level1: { + level2: { + level3: { + level4: 'logs nested objects correctly', + }, + }, + }, + }, + }, + }); + return { error }; + } + logger.error(buildServerSideErrorEntry()); + expect(readLog()).toMatchInlineSnapshot(` + { + "application": { + "name": "One App", + "version": "1.2.3-abc123", + }, + "device": { + "agent": "mockType mockArch", + "id": "mockHostname:1234", + }, + "error": { + "message": "something broke", + "name": "Error", + "stacktrace": "Error: something broke + at methodA (resource-a.js:1:1) + at methodB (resource-b.js:1:1) + ", + }, + "level": "error", + "message": "something broke", + "metaData": { + "moduleID": "healthy-frank", + "nestedObject": { + "level1": { + "level2": { + "level3": { + "level4": "logs nested objects correctly", + }, + }, + }, + }, + }, + "schemaVersion": "0.3.0", + "timestamp": "2023-08-09T22:06:34.070Z", + } + `); + }); + }); +}); diff --git a/__tests__/server/utils/logging/development-formatters/__snapshots__/friendly.spec.js.snap b/__tests__/server/utils/logging/development-formatters/__snapshots__/friendly.spec.js.snap deleted file mode 100644 index 0c3b04feb..000000000 --- a/__tests__/server/utils/logging/development-formatters/__snapshots__/friendly.spec.js.snap +++ /dev/null @@ -1,49 +0,0 @@ -// Jest Snapshot v1, https://goo.gl/fbAQLP - -exports[`friendly formatter module map polling finishes with errors finished the moduleMapSpinner with success 1`] = ` -[ - "Polling Holocron Module map failed", -] -`; - -exports[`friendly formatter module map polling finishes with errors writes the log statement 1`] = ` -"error: sample test error -" -`; - -exports[`friendly formatter module map polling finishes with no updates finished the moduleMapSpinner with success 1`] = ` -[ - "Polled Holocron Module map: no updates (polling again in 5s)", -] -`; - -exports[`friendly formatter module map polling finishes with updates finished the moduleMapSpinner with success 1`] = ` -[ - "Polled Holocron Module map: 2 updates", -] -`; - -exports[`friendly formatter module map polling finishes with updates writes a re-formatted log statement 1`] = ` -"Modules updated: { - "a": "1.2.3", - "b": "4.5.6" -}" -`; - -exports[`friendly formatter pretty-prints an incoming request 1`] = `"error: 🌍 ➡ 💻 200 OK GET https://example.com/resource 13ms"`; - -exports[`friendly formatter prints the level with color 1`] = `"error: hello"`; - -exports[`friendly formatter startup ssrServer bootstrap of holocron module loading failed stops the appServerSpinner with failure when it is enabled 1`] = ` -[ - "Failed to load Holocron module (modulesPath/moduleName/version/moduleName.server.js)", -] -`; - -exports[`friendly formatter startup ssrServer bootstrap of holocron module loading failed stops the appServerSpinner with failure when the root module is not in the module map 1`] = ` -[ - "unable to find root module "not-in-module-map" in the module map", -] -`; - -exports[`friendly formatter unknown type is formatted by util.format 1`] = `"error: hello, world"`; diff --git a/__tests__/server/utils/logging/development-formatters/__snapshots__/verbose.spec.js.snap b/__tests__/server/utils/logging/development-formatters/__snapshots__/verbose.spec.js.snap deleted file mode 100644 index 0ec0e4575..000000000 --- a/__tests__/server/utils/logging/development-formatters/__snapshots__/verbose.spec.js.snap +++ /dev/null @@ -1,9 +0,0 @@ -// Jest Snapshot v1, https://goo.gl/fbAQLP - -exports[`verbose formatter pretty-prints an incoming request 1`] = `"error: 🌍 ➡ 💻 200 OK GET https://example.com/resource 12/13ms"`; - -exports[`verbose formatter pretty-prints an outgoing request 1`] = `"error: 💻 ➡ 🗄️ 200 OK GET https://example.com/resource 13ms"`; - -exports[`verbose formatter prints the level with color 1`] = `"error: hello"`; - -exports[`verbose formatter unknown type is formatted by util.format 1`] = `"error: hello, world"`; diff --git a/__tests__/server/utils/logging/development-formatters/friendly.spec.js b/__tests__/server/utils/logging/development-formatters/friendly.spec.js deleted file mode 100644 index b575d8d75..000000000 --- a/__tests__/server/utils/logging/development-formatters/friendly.spec.js +++ /dev/null @@ -1,389 +0,0 @@ -/* - * Copyright 2019 American Express Travel Related Services Company, Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express - * or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -import ora from 'ora'; - -import { beforeWrite, afterWrite, formatter } from '../../../../../src/server/utils/logging/development-formatters/friendly'; - -jest.mock('chalk'); - -jest.mock('ora', () => { - const mockOra = jest.fn((opts) => { - const spinner = { - __opts: opts, - start: jest.fn(() => spinner), - stop: jest.fn(() => spinner), - succeed: jest.fn(() => spinner), - fail: jest.fn(() => spinner), - warn: jest.fn(() => spinner), - info: jest.fn(() => spinner), - stopAndPersist: jest.fn(() => spinner), - clear: jest.fn(() => spinner), - render: jest.fn(() => spinner), - frame: jest.fn(() => spinner), - text: jest.fn(() => spinner), - color: jest.fn(() => spinner), - }; - - mockOra.mock.returns.push(spinner); - - return spinner; - }); - - mockOra.mock.returns = []; - - const origMockClear = mockOra.mockClear; - mockOra.mockClear = (...args) => { - mockOra.mock.returns = []; - return origMockClear.apply(this, args); - }; - - return mockOra; -}); - -const [ - oneAppDevCdnSpinner, - oneAppDevProxySpinner, - metricsServerSpinner, - appServerSpinner, - moduleMapSpinner, -] = ora.mock.returns; - -describe('friendly', () => { - describe('beforeWrite', () => { - it('is a function', () => expect(beforeWrite).toBeInstanceOf(Function)); - - it('clears all active spinners', () => { - oneAppDevCdnSpinner.isEnabled = true; - oneAppDevCdnSpinner.clear.mockClear(); - expect(oneAppDevCdnSpinner.clear).not.toHaveBeenCalled(); - beforeWrite(); - expect(oneAppDevCdnSpinner.clear).toHaveBeenCalledTimes(1); - }); - }); - - describe('afterWrite', () => { - it('is a function', () => expect(afterWrite).toBeInstanceOf(Function)); - - it('starts all active spinners', () => { - oneAppDevCdnSpinner.isEnabled = true; - oneAppDevCdnSpinner.start.mockClear(); - expect(oneAppDevCdnSpinner.start).not.toHaveBeenCalled(); - afterWrite(); - expect(oneAppDevCdnSpinner.start).toHaveBeenCalledTimes(1); - }); - }); - - describe('formatter', () => { - it('prints the level with color', () => { - expect(formatter('error', 'hello')).toMatchSnapshot(); - }); - - it('pretty-prints an incoming request', () => { - const entry = { - type: 'request', - request: { - direction: 'in', - protocol: 'https', - address: { - uri: 'https://example.com/resource', - }, - metaData: { - method: 'GET', - correlationId: '123', - // null to explicitly signal no value, undefined if not expected for every request - host: 'example.com', - referrer: 'https://example.com/other-resource', - userAgent: 'Browser/9.0 (compatible; ABCD 100.0; Doors OZ 81.4; Plane/1.0)', - location: undefined, - }, - timings: { - duration: 13, - ttfb: 12, - }, - statusCode: 200, - statusText: 'OK', - }, - }; - expect(formatter('error', entry)).toMatchSnapshot(); - }); - - it('skips showing external-request types', () => { - expect(formatter('error', { - type: 'request', - request: { - direction: 'out', - protocol: 'https', - address: { - uri: 'https://example.com/resource', - }, - metaData: { - method: 'GET', - // null to explicitly signal no value, undefined if not expected for every request - correlationId: '123', - }, - timings: { - duration: 13, - }, - statusCode: 200, - statusText: 'OK', - }, - })).toBe(null); - }); - - describe('unknown type', () => { - it('is formatted by util.format', () => { - expect(formatter('error', 'hello, %s', 'world')).toMatchSnapshot(); - }); - }); - - describe('startup', () => { - describe('environment configuration', () => { - it('skips writing warnings of using server config values for the client', () => { - expect(formatter('error', 'WARNING: ONE_CLIENT_SAMPLE_URL unspecified, using ONE_SAMPLE_URL')).toBe(null); - }); - - it('skips writing the end result of a validated and processes env var', () => { - expect(formatter('error', 'env var ONE_SAMPLE_URL=https://example.org (string)')).toBe(null); - }); - - it('skips writing the compiled client configuration', () => { - expect(formatter('error', 'client config setup from process.env:', { client: true })).toBe(null); - }); - - it('skips writing the compiled server configuration', () => { - expect(formatter('error', 'server config setup from process.env:', { server: true })).toBe(null); - }); - }); - - describe('one-app-dev-cdn starts up successfully', () => { - it('stops the oneAppDevCdnSpinner with success', () => { - oneAppDevCdnSpinner.succeed.mockClear(); - formatter('level', '👕 one-app-dev-cdn server listening on port 3001'); - expect(oneAppDevCdnSpinner.succeed).toHaveBeenCalledTimes(1); - expect(oneAppDevCdnSpinner.isEnabled).toBe(false); - }); - - it('starts the oneAppDevProxySpinner when one-app-dev-cdn starts up successfully', () => { - oneAppDevProxySpinner.start.mockClear(); - formatter('level', '👕 one-app-dev-cdn server listening on port 3001'); - expect(oneAppDevProxySpinner.start).toHaveBeenCalledTimes(1); - expect(oneAppDevProxySpinner.isEnabled).toBe(true); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', '👕 one-app-dev-cdn server listening on port 3001')).toBe(null); - }); - }); - - describe('one-app-dev-proxy starts up successfully', () => { - it('stops the oneAppDevProxySpinner with success', () => { - oneAppDevProxySpinner.succeed.mockClear(); - formatter('level', '👖 one-app-dev-proxy server listening on port 3002'); - expect(oneAppDevProxySpinner.succeed).toHaveBeenCalledTimes(1); - expect(oneAppDevProxySpinner.isEnabled).toBe(false); - }); - - it('starts the appServerSpinner and metricsServerSpinner when one-app-dev-proxy starts up successfully', () => { - appServerSpinner.start.mockClear(); - metricsServerSpinner.start.mockClear(); - formatter('level', '👖 one-app-dev-proxy server listening on port 3002'); - expect(appServerSpinner.start).toHaveBeenCalledTimes(1); - expect(appServerSpinner.isEnabled).toBe(true); - expect(metricsServerSpinner.start).toHaveBeenCalledTimes(1); - expect(metricsServerSpinner.isEnabled).toBe(true); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', '👖 one-app-dev-proxy server listening on port 3002')).toBe(null); - }); - }); - - describe('ssrServer starts up successfully', () => { - it('stops the appServerSpinner with success', () => { - appServerSpinner.succeed.mockClear(); - formatter('level', '🌎 One App server listening on port 3000'); - expect(appServerSpinner.succeed).toHaveBeenCalledTimes(1); - expect(appServerSpinner.isEnabled).toBe(false); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', '🌎 One App server listening on port 3000')).toBe(null); - }); - }); - - describe('metrics server starts up successfully', () => { - it('stops the metricsServerSpinner with success', () => { - metricsServerSpinner.succeed.mockClear(); - formatter('level', '📊 Metrics server listening on port'); - expect(metricsServerSpinner.succeed).toHaveBeenCalledTimes(1); - expect(metricsServerSpinner.isEnabled).toBe(false); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', '📊 Metrics server listening on port')).toBe(null); - }); - }); - - describe('ssrServer bootstrap of holocron module loading failed', () => { - it('stops the appServerSpinner with failure when it is enabled', () => { - appServerSpinner.fail.mockClear(); - appServerSpinner.isEnabled = true; - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'Failed to load Holocron module (modulesPath/moduleName/version/moduleName.server.js)'); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(appServerSpinner.fail).toHaveBeenCalledTimes(1); - expect(appServerSpinner.fail.mock.calls[0]).toMatchSnapshot(); - expect(appServerSpinner.isEnabled).toBe(false); - }); - - it('stops the appServerSpinner with failure when the root module is not in the module map', () => { - appServerSpinner.fail.mockClear(); - appServerSpinner.isEnabled = true; - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', new Error('unable to find root module "not-in-module-map" in the module map')); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(appServerSpinner.fail).toHaveBeenCalledTimes(1); - expect(appServerSpinner.fail.mock.calls[0]).toMatchSnapshot(); - expect(appServerSpinner.isEnabled).toBe(false); - }); - - it('leaves a disabled appServerSpinner alone when it is not enabled', () => { - appServerSpinner.fail.mockClear(); - appServerSpinner.isEnabled = false; - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'Failed to load Holocron module (modulesPath/moduleName/version/moduleName.server.js)'); - expect(setImmediate).not.toHaveBeenCalled(); - expect(appServerSpinner.fail).not.toHaveBeenCalled(); - expect(appServerSpinner.isEnabled).toBe(false); - }); - - it('skips writing the log statement when the appServerSpinner is enabled', () => { - appServerSpinner.isEnabled = true; - expect(formatter('error', 'Failed to load Holocron module (modulesPath/moduleName/version/moduleName.server.js)')).toBe(null); - }); - - it('writes the log statement when the appServerSpinner is not enabled', () => { - appServerSpinner.isEnabled = false; - expect(formatter('error', 'Failed to load Holocron module (modulesPath/moduleName/version/moduleName.server.js)')).not.toBe(null); - }); - }); - }); - - describe('module map polling', () => { - describe('starts', () => { - it('starts the moduleMapSpinner', () => { - moduleMapSpinner.start.mockClear(); - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'pollModuleMap: polling...'); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(moduleMapSpinner.start).toHaveBeenCalledTimes(1); - expect(moduleMapSpinner.isEnabled).toBe(true); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', 'pollModuleMap: polling...')).toBe(null); - }); - }); - - describe('finishes with no updates', () => { - it('finished the moduleMapSpinner with success', () => { - moduleMapSpinner.succeed.mockClear(); - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'pollModuleMap: no updates, looking again in 5s'); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(moduleMapSpinner.succeed).toHaveBeenCalledTimes(1); - expect(moduleMapSpinner.succeed.mock.calls[0]).toMatchSnapshot(); - expect(moduleMapSpinner.isEnabled).toBe(false); - }); - - it('skips writing the log statement', () => { - expect(formatter('error', 'pollModuleMap: no updates, looking again in 5s')).toBe(null); - }); - }); - - describe('finishes with updates', () => { - it('finished the moduleMapSpinner with success', () => { - moduleMapSpinner.succeed.mockClear(); - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'pollModuleMap: 2 modules loaded/updated:', { a: '1.2.3', b: '4.5.6' }); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(moduleMapSpinner.succeed).toHaveBeenCalledTimes(1); - expect(moduleMapSpinner.succeed.mock.calls[0]).toMatchSnapshot(); - expect(moduleMapSpinner.isEnabled).toBe(false); - }); - - it('writes a re-formatted log statement', () => { - expect(formatter('error', 'pollModuleMap: 2 modules loaded/updated:', { a: '1.2.3', b: '4.5.6' })).toMatchSnapshot(); - }); - }); - - describe('finishes with errors', () => { - it('finished the moduleMapSpinner with success', () => { - moduleMapSpinner.warn.mockClear(); - jest.spyOn(global, 'setImmediate').mockClear(); - formatter('level', 'pollModuleMap: error polling'); - expect(setImmediate).toHaveBeenCalledTimes(1); - setImmediate.mock.calls[0][0](); - expect(moduleMapSpinner.warn).toHaveBeenCalledTimes(1); - expect(moduleMapSpinner.warn.mock.calls[0]).toMatchSnapshot(); - expect(moduleMapSpinner.isEnabled).toBe(false); - }); - - it('writes the log statement', () => { - const err = new Error('sample test error'); - err.stack = 'sample test error\n'; - const formattedError = formatter('error', 'pollModuleMap: error polling', err) - .replace('[', '') - .replace(']', ''); - expect(formattedError).toMatchSnapshot(); - }); - }); - describe('monitor', () => { - it('skips writing the log statement for setting up the monitor', () => { - expect(formatter('error', 'pollModuleMap: setting up polling monitor to run every 5s')).toBe(null); - }); - it('skips writing the log statement for when the monitor runs', () => { - expect(formatter('error', 'pollModuleMap: running polling monitor')).toBe(null); - }); - it('skips writing the log statement for when polling is not considered stopped', () => { - expect( - formatter( - 'error', - 'pollModuleMap: polling is working as expected. Last poll: 5ms ago, Max poll: 6ms.' - ) - ).toBe(null); - }); - it('skips writing the log statement for when polling is considered stopped', () => { - expect( - formatter( - 'error', - 'pollModuleMap: polling has unexpectedly stopped. Last poll: 7ms ago, Max poll: 5ms.' - ) - ).toBe(null); - }); - it('skips writing the log statement for when polling has been restarted by the monitor', () => { - expect(formatter('error', 'pollModuleMap: restarted polling')).toBe(null); - }); - }); - }); - }); -}); diff --git a/__tests__/server/utils/logging/development-formatters/index.spec.js b/__tests__/server/utils/logging/development-formatters/index.spec.js deleted file mode 100644 index 55540a6d6..000000000 --- a/__tests__/server/utils/logging/development-formatters/index.spec.js +++ /dev/null @@ -1,54 +0,0 @@ -/* - * Copyright 2019 American Express Travel Related Services Company, Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express - * or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -jest.mock('../../../../../src/server/utils/logging/development-formatters/verbose', () => 'verbose export'); -jest.mock('../../../../../src/server/utils/logging/development-formatters/friendly', () => 'friendly export'); - -describe('index', () => { - let index; - - beforeEach(() => { - jest.resetModules(); - }); - - function load(logFormat = '') { - jest.doMock('yargs', () => ({ - argv: { - logFormat, - }, - })); - index = require('../../../../../src/server/utils/logging/development-formatters'); - } - - it('returns the friendly formatter by default', () => { - process.stdout.clearLine = jest.fn(); - load(); - expect(index).toBe('friendly export'); - }); - - it('returns the verbose formatter when give CLI argument logging=verbose', () => { - process.stdout.clearLine = jest.fn(); - load('verbose'); - expect(index).toBe('verbose export'); - }); - - it('returns the verbose formatter when stdout does not support fancy CLIs', () => { - // ex: being piped to a file, we don't need/want the spinners - delete process.stdout.clearLine; - load('verbose'); - expect(index).toBe('verbose export'); - }); -}); diff --git a/__tests__/server/utils/logging/development-formatters/verbose.spec.js b/__tests__/server/utils/logging/development-formatters/verbose.spec.js deleted file mode 100644 index 3eefc7221..000000000 --- a/__tests__/server/utils/logging/development-formatters/verbose.spec.js +++ /dev/null @@ -1,102 +0,0 @@ -/* - * Copyright 2019 American Express Travel Related Services Company, Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express - * or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -import { beforeWrite, afterWrite, formatter } from '../../../../../src/server/utils/logging/development-formatters/verbose'; - -jest.mock('chalk'); - -describe('verbose', () => { - describe('beforeWrite', () => { - it('is undefined', () => { - expect(beforeWrite).toBe(undefined); - }); - }); - - describe('afterWrite', () => { - it('is undefined', () => { - expect(afterWrite).toBe(undefined); - }); - }); - - describe('formatter', () => { - it('prints the level with color', () => { - expect(formatter('error', 'hello')).toMatchSnapshot(); - }); - - it('drops lower levels', () => { - expect(formatter('debug', 1, 2, 3)).toBe(null); - }); - - it('pretty-prints an incoming request', () => { - const entry = { - type: 'request', - request: { - direction: 'in', - protocol: 'https', - address: { - uri: 'https://example.com/resource', - }, - metaData: { - method: 'GET', - correlationId: '123', - // null to explicitly signal no value, undefined if not expected for every request - host: 'example.com', - referrer: 'https://example.com/other-resource', - userAgent: 'Browser/8.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)', - location: undefined, - }, - timings: { - duration: 13, - ttfb: 12, - }, - statusCode: 200, - statusText: 'OK', - }, - }; - expect(formatter('error', entry)).toMatchSnapshot(); - }); - - it('pretty-prints an outgoing request', () => { - const entry = { - type: 'request', - request: { - direction: 'out', - protocol: 'https', - address: { - uri: 'https://example.com/resource', - }, - metaData: { - method: 'GET', - // null to explicitly signal no value, undefined if not expected for every request - correlationId: '123', - }, - timings: { - duration: 13, - }, - statusCode: 200, - statusText: 'OK', - }, - }; - expect(formatter('error', entry)).toMatchSnapshot(); - }); - - describe('unknown type', () => { - it('is formatted by util.format', () => { - expect(formatter('error', 'hello, %s', 'world')).toMatchSnapshot(); - }); - }); - }); -}); diff --git a/__tests__/server/utils/logging/fastifyPlugin.spec.js b/__tests__/server/utils/logging/fastifyPlugin.spec.js index c08502b62..6adb73029 100644 --- a/__tests__/server/utils/logging/fastifyPlugin.spec.js +++ b/__tests__/server/utils/logging/fastifyPlugin.spec.js @@ -21,8 +21,8 @@ import fastifyPlugin, { $ResponseBuilder, setConfigureRequestLog, } from '../../../../src/server/utils/logging/fastifyPlugin'; -import logger from '../../../../src/server/utils/logging/logger'; +jest.mock('pino'); jest.mock('../../../../src/server/utils/logging/logger'); describe('fastifyPlugin', () => { @@ -368,6 +368,7 @@ describe('fastifyPlugin', () => { const request = { headers: {}, + log: { info: jest.fn() }, }; const reply = { getHeader: jest.fn(), @@ -379,6 +380,7 @@ describe('fastifyPlugin', () => { expect(process.hrtime).toHaveBeenCalledTimes(2); expect(request).toEqual({ headers: {}, + log: request.log, [$ResponseBuilder]: 0.001, [$RequestFullDuration]: 0.001, }); @@ -404,7 +406,10 @@ describe('fastifyPlugin', () => { expect(process.hrtime).toHaveBeenCalledTimes(0); const request = { - headers: { + headers: {}, + log: { + error: jest.fn(), + info: jest.fn(), }, }; const reply = { @@ -417,9 +422,8 @@ describe('fastifyPlugin', () => { await fastify.onSend(request, reply); await fastify.onResponse(request, reply); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ - type: 'request', + expect(request.log.info).toHaveBeenCalledTimes(1); + expect(request.log.info).toHaveBeenCalledWith({ request: { address: { uri: '', @@ -478,6 +482,7 @@ describe('fastifyPlugin', () => { hostname: 'amex.com', originalUrl: 'amex.com', method: 'GET', + log: { info: jest.fn() }, }; const reply = { getHeader: jest.fn((header) => { @@ -501,9 +506,8 @@ describe('fastifyPlugin', () => { await fastify.onSend(request, reply); await fastify.onResponse(request, reply); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ - type: 'request', + expect(request.log.info).toHaveBeenCalledTimes(1); + expect(request.log.info).toHaveBeenCalledWith({ request: { address: { uri: 'https://amex.com:1234/amex.com', @@ -549,13 +553,13 @@ describe('fastifyPlugin', () => { expect(process.hrtime).toHaveBeenCalledTimes(0); const request = { - headers: { - }, + headers: {}, store: { getState: () => ({ getIn: () => 'us_en', }), }, + log: { info: jest.fn() }, }; const reply = { getHeader: jest.fn(), @@ -567,9 +571,8 @@ describe('fastifyPlugin', () => { await fastify.onSend(request, reply); await fastify.onResponse(request, reply); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ - type: 'request', + expect(request.log.info).toHaveBeenCalledTimes(1); + expect(request.log.info).toHaveBeenCalledWith({ request: { address: { uri: '', @@ -617,9 +620,9 @@ describe('fastifyPlugin', () => { setConfigureRequestLog(mutateLog); const request = { - headers: { - }, + headers: {}, raw: 'raw-request', + log: { info: jest.fn() }, }; const reply = { getHeader: jest.fn(), @@ -662,11 +665,10 @@ describe('fastifyPlugin', () => { ttfb: 0, }, }, - type: 'request', }, }); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith('log changed'); + expect(request.log.info).toHaveBeenCalledTimes(1); + expect(request.log.info).toHaveBeenCalledWith('log changed'); }); it('negative ttfb', async () => { @@ -682,8 +684,8 @@ describe('fastifyPlugin', () => { fastifyPlugin(fastify, null, jest.fn()); const request = { - headers: { - }, + headers: {}, + log: { info: jest.fn() }, }; const reply = { getHeader: jest.fn(), @@ -695,8 +697,8 @@ describe('fastifyPlugin', () => { await fastify.onResponse(request, reply); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ + expect(request.log.info).toHaveBeenCalledTimes(1); + expect(request.log.info).toHaveBeenCalledWith({ request: { address: { uri: '', @@ -724,16 +726,14 @@ describe('fastifyPlugin', () => { ttfb: null, }, }, - type: 'request', }); }); }); it('catches and logs errors', async () => { - const errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); - const request = { headers: {}, + log: { error: jest.fn() }, }; const reply = { getHeader: jest.fn(), @@ -757,13 +757,14 @@ describe('fastifyPlugin', () => { throw boomError; }); await expect(() => fastify.onResponse(request, reply)).rejects.toEqual(boomError); - expect(errorSpy).toHaveBeenCalledWith(boomError); + expect(request.log.error).toHaveBeenCalledWith(boomError); }); }); describe('setConfigureRequestLog', () => { it('resets to default', async () => { const request = { + log: { info: jest.fn() }, headers: {}, }; const reply = { @@ -790,7 +791,7 @@ describe('fastifyPlugin', () => { await fastify.onResponse(request, reply); - expect(logger.info.mock.calls[0][0]).toMatchInlineSnapshot(` + expect(request.log.info.mock.calls[0][0]).toMatchInlineSnapshot(` { "request": { "address": { @@ -819,7 +820,6 @@ describe('fastifyPlugin', () => { "ttfb": 0, }, }, - "type": "request", } `); }); diff --git a/__tests__/server/utils/logging/level-dropper.spec.js b/__tests__/server/utils/logging/level-dropper.spec.js deleted file mode 100644 index a761012d2..000000000 --- a/__tests__/server/utils/logging/level-dropper.spec.js +++ /dev/null @@ -1,44 +0,0 @@ -/* - * Copyright 2019 American Express Travel Related Services Company, Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express - * or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -describe('level-dropper', () => { - function load(logLevel = 'info') { - jest.resetModules(); - jest.setMock('yargs', { argv: { logLevel } }); - - return require('../../../../src/server/utils/logging/level-dropper').default; - } - - it('keeps error when logLevel is error', () => expect(load('error')('error')).toBe(false)); - it('drops warn when logLevel is error', () => expect(load('error')('warn')).toBe(true)); - it('drops log when logLevel is error', () => expect(load('error')('log')).toBe(true)); - it('drops info when logLevel is error', () => expect(load('error')('info')).toBe(true)); - - it('keeps error when logLevel is warn', () => expect(load('warn')('error')).toBe(false)); - it('keeps warn when logLevel is warn', () => expect(load('warn')('warn')).toBe(false)); - it('drops log when logLevel is warn', () => expect(load('warn')('log')).toBe(true)); - it('drops info when logLevel is warn', () => expect(load('warn')('info')).toBe(true)); - - it('keeps error when logLevel is log', () => expect(load('log')('error')).toBe(false)); - it('keeps warn when logLevel is log', () => expect(load('log')('warn')).toBe(false)); - it('keeps log when logLevel is log', () => expect(load('log')('log')).toBe(false)); - it('drops info when logLevel is log', () => expect(load('log')('info')).toBe(true)); - - it('keeps error when logLevel is info', () => expect(load('info')('error')).toBe(false)); - it('keeps warn when logLevel is info', () => expect(load('info')('warn')).toBe(false)); - it('keeps log when logLevel is info', () => expect(load('info')('log')).toBe(false)); - it('keeps info when logLevel is info', () => expect(load('info')('info')).toBe(false)); -}); diff --git a/__tests__/server/utils/logging/logger.spec.js b/__tests__/server/utils/logging/logger.spec.js index 8677ea513..f8c8afe75 100644 --- a/__tests__/server/utils/logging/logger.spec.js +++ b/__tests__/server/utils/logging/logger.spec.js @@ -13,12 +13,20 @@ * or implied. See the License for the specific language governing * permissions and limitations under the License. */ +import deepmerge from 'deepmerge'; + +jest.mock('yargs', () => ({ + argv: { + logLevel: 'debug', + }, +})); describe('logger', () => { let logger; - let Lumberjack; - let productionFormatter; - let developmentFormatter; + let pino; + let productionConfig; + let baseConfig; + let developmentStream; function load(nodeEnv) { jest.resetModules(); @@ -29,40 +37,35 @@ describe('logger', () => { delete process.env.NODE_ENV; } - jest.mock('@americanexpress/lumberjack', () => jest.fn()); - jest.mock('../../../../src/server/utils/logging/production-formatter', () => jest.fn(() => 'prod')); - jest.mock('../../../../src/server/utils/logging/development-formatters', () => ({ - formatter: jest.fn(() => 'dev'), - beforeWrite: jest.fn(), - afterWrite: jest.fn(), - })); - - Lumberjack = require('@americanexpress/lumberjack'); - productionFormatter = require('../../../../src/server/utils/logging/production-formatter'); - developmentFormatter = require('../../../../src/server/utils/logging/development-formatters'); - + jest.mock('pino', () => jest.fn(() => 'pino')); + pino = require('pino'); + baseConfig = require('../../../../src/server/utils/logging/config/base').default; + productionConfig = require('../../../../src/server/utils/logging/config/production').default; + developmentStream = require('../../../../src/server/utils/logging/config/development').default; logger = require('../../../../src/server/utils/logging/logger').default; } - it('is an instance of @americanexpress/lumberjack', () => { + it('is pino logger', () => { load(); - expect(logger).toBeInstanceOf(Lumberjack); - expect(logger).toBe(Lumberjack.mock.instances[0]); + expect(logger).toBe('pino'); }); it('uses the production formatter by default', () => { load(); - expect(Lumberjack.mock.calls[0][0]).toHaveProperty('formatter', productionFormatter); + expect(pino).toHaveBeenCalledTimes(1); + expect(pino).toHaveBeenCalledWith(deepmerge(baseConfig, productionConfig), undefined); }); it('uses a development formatter when NODE_ENV is development', () => { load('development'); - expect(Lumberjack.mock.calls[0][0]).toBe(developmentFormatter); + expect(pino).toHaveBeenCalledTimes(1); + expect(pino).toHaveBeenCalledWith(baseConfig, developmentStream); }); it('uses the production formatter when the log-format flag is set to machine', () => { - jest.mock('yargs', () => ({ argv: { logFormat: 'machine' } })); + jest.mock('yargs', () => ({ argv: { logFormat: 'machine', logLevel: 'info' } })); load(); - expect(Lumberjack.mock.calls[0][0]).toHaveProperty('formatter', productionFormatter); + expect(pino).toHaveBeenCalledTimes(1); + expect(pino).toHaveBeenCalledWith(deepmerge(baseConfig, productionConfig), undefined); }); }); diff --git a/__tests__/server/utils/logging/production-formatter.spec.js b/__tests__/server/utils/logging/production-formatter.spec.js deleted file mode 100644 index cf1459351..000000000 --- a/__tests__/server/utils/logging/production-formatter.spec.js +++ /dev/null @@ -1,259 +0,0 @@ -/* - * Copyright 2019 American Express Travel Related Services Company, Inc. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express - * or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -import util from 'util'; - -jest.mock('../../../../src/server/utils/readJsonFile', () => () => ({ buildVersion: '1.2.3-abc123' })); -jest.mock('os', () => ({ - hostname: jest.fn(() => 'host-123'), - type: jest.fn(() => 'Darwin'), - arch: jest.fn(() => 'x64'), -})); - -function createErrorWithMockedStacktrace(msg) { - const err = new Error(msg); - err.stack = `Error: test error - at Object. (one-app/__tests__/server/utils/logging/production-formatter.spec.js:36:64) - at Object.asyncFn (one-app/node_modules/jest-jasmine2/build/jasmine_async.js:124:345) - at resolve (one-app/node_modules/jest-jasmine2/build/queue_runner.js:46:12) - at new Promise () - at mapper (one-app/node_modules/jest-jasmine2/build/queue_runner.js:34:499) - at promise.then (one-app/node_modules/jest-jasmine2/build/queue_runner.js:74:39) - at - at process._tickCallback (internal/process/next_tick.js:188:7)`; - - return err; -} - -describe('production-formatter', () => { - let formatter; - jest.spyOn(Date.prototype, 'toISOString').mockImplementation(() => '2018-03-02T02:39:32.948Z'); - jest.spyOn(util, 'format'); - - function load(pid) { - jest.resetModules(); - - Object.defineProperty(process, 'pid', { - writable: true, - value: pid || 1234, - }); - formatter = require('../../../../src/server/utils/logging/production-formatter').default; - } - - it('is a function', () => { - load(); - expect(typeof formatter).toBe('function'); - }); - - it('encodes as parseable JSON', () => { - load(); - const entry = formatter('error', 1, 2, 3); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - - it('drops lower levels', () => { - load(); - expect(formatter('debug', 1, 2, 3)).toBe(null); - }); - - describe('errors', () => { - it('encodes as parseable JSON', () => { - load(); - const entry = formatter('error', 'unable to do the thing', createErrorWithMockedStacktrace('test error')); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - - it('puts a lone error in the error field', () => { - expect.assertions(2); - load(); - const parsed = JSON.parse(formatter('error', createErrorWithMockedStacktrace('test error'))); - expect(parsed).toHaveProperty('error'); - expect(parsed.error).toMatchSnapshot(); - }); - - it('does not include a message key when given a lone error', () => { - expect.assertions(1); - load(); - const parsed = JSON.parse(formatter('error', new Error('irrelevant'))); - expect(parsed).not.toHaveProperty('message'); - }); - - it('puts an error with other arguments in the error field and uses only the other args for the message', () => { - expect.assertions(4); - load(); - const parsed = JSON.parse(formatter('error', createErrorWithMockedStacktrace('test error'), 'say hi %i times', 7)); - expect(parsed).toHaveProperty('error'); - expect(parsed).toHaveProperty('message'); - expect(parsed.error).toMatchSnapshot(); - expect(parsed.message).toBe('say hi 7 times'); - }); - - it('puts an error paired with a message in the error field', () => { - expect.assertions(4); - load(); - const parsed = JSON.parse(formatter('error', 'unable to do the thing', createErrorWithMockedStacktrace('test error'))); - expect(parsed).toHaveProperty('error'); - expect(parsed).toHaveProperty('message'); - expect(parsed.error).toMatchSnapshot(); - expect(parsed.message).toBe('unable to do the thing'); - }); - - it('uses the error in the message when the error is paired with a message and other arguments', () => { - expect.assertions(4); - load(); - const parsed = JSON.parse(formatter('error', 'unable to do the thing %O %d times', createErrorWithMockedStacktrace('test error'), 12)); - const errorText = parsed.message - .replace('[', '') - .replace(']', ''); - expect(parsed).toHaveProperty('error'); - expect(parsed).toHaveProperty('message'); - expect(parsed.error).toMatchSnapshot(); - expect(errorText).toMatchSnapshot(); - }); - - it('records the error message as if not present', () => { - expect.assertions(2); - load(); - const err = createErrorWithMockedStacktrace('test error'); - delete err.message; - const parsed = JSON.parse(formatter('error', 'unable to do the thing', err)); - expect(parsed).toHaveProperty('error'); - expect(parsed.error).toHaveProperty('message', ''); - }); - - it('records the error stacktrace as if not present', () => { - expect.assertions(2); - load(); - const err = createErrorWithMockedStacktrace('test error'); - delete err.stack; - const parsed = JSON.parse(formatter('error', 'unable to do the thing', err)); - expect(parsed).toHaveProperty('error'); - expect(parsed.error).toHaveProperty('stacktrace', ''); - }); - - it('encodes ClientReportedError Error as parseable JSON', () => { - function buildClientErrorEntry() { - const error = new Error('something broke'); - Object.assign(error, { - name: 'ClientReportedError', - stack: 'Error: something broke\n at methodA (resource-a.js:1:1)\n at methodB (resource-b.js:1:1)\n', - userAgent: 'Browser/5.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)', - uri: 'https://example.com/page-the/error/occurred-on', - metaData: { - moduleID: 'healthy-frank', - code: '500', - collectionMethod: 'applicationError', - correlationId: '123abc', - }, - }); - return error; - } - - load(); - const entry = formatter('error', buildClientErrorEntry()); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - - it('encodes Server Reported Error as parseable JSON with nested metadata objects', () => { - function buildServerSideErrorEntry() { - const error = new Error('something broke'); - Object.assign(error, { - stack: 'Error: something broke\n at methodA (resource-a.js:1:1)\n at methodB (resource-b.js:1:1)\n', - metaData: { - moduleID: 'healthy-frank', - nestedObject: { - level1: { - level2: { - level3: { - level4: 'logs nested objects correctly', - }, - }, - }, - }, - }, - }); - return error; - } - - load(); - const entry = formatter('error', buildServerSideErrorEntry()); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - }); - - describe('types', () => { - it('encodes request as parseable JSON', () => { - function buildRequestEntry() { - return { - type: 'request', - request: { - direction: 'in', - protocol: 'https', - address: { - url: 'https://example.org/server', - }, - metaData: { - method: 'GET', - correlationId: '123', - // null to explicitly signal no value, undefined if not expected for every request - host: 'example.org', - referrer: 'https://example.org/other-page', - userAgent: 'Browser/8.0 (compatible; WXYZ 100.0; Doors LQ 81.4; Boat/1.0)', - location: undefined, - }, - timings: { // https://www.w3.org/TR/navigation-timing/ - // navigationStart: 0, - // redirectStart: 0, - // redirectEnd: 0, - // fetchStart: 0, - // domainLookupStart: 10, - // domainLookupEnd: 20, - // connectStart: 30, - // secureConnectionStart: 40, - // connectEnd: 50, - // requestStart: 60, - // requestEnd: 70, // optional? not part of the W3C spec - // responseStart: 80, - // responseEnd: 90, - duration: 10, - ttfb: 20, - }, - statusCode: 200, - statusText: 'OK', - }, - }; - } - - load(); - const entry = formatter('error', buildRequestEntry()); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - - it('uses the default util.format when given an unknown type', () => { - load(); - util.format.mockClear(); - const entry = formatter('error', { type: 'yolo' }); - expect(util.format).toHaveBeenCalledTimes(1); - expect(() => JSON.parse(entry)).not.toThrowError(); - expect(JSON.parse(entry)).toMatchSnapshot(); - }); - }); -}); diff --git a/__tests__/server/utils/logging/setup.spec.js b/__tests__/server/utils/logging/setup.spec.js index 3dd53a52c..fe4c7f639 100644 --- a/__tests__/server/utils/logging/setup.spec.js +++ b/__tests__/server/utils/logging/setup.spec.js @@ -16,11 +16,27 @@ import url from 'url'; +jest.mock('yargs', () => ({ + argv: { + logLevel: 'debug', + }, +})); + describe('setup', () => { let monkeypatches; let logger; let startTimer; + const logMethods = ['error', 'warn', 'log', 'info', 'debug']; + const originalConsole = logMethods.reduce((acc, curr) => ({ + ...acc, + [curr]: console[curr], + }), {}); + + afterEach(() => { + logMethods.forEach((method) => { console[method] = originalConsole[method]; }); + }); + function load() { jest.resetModules(); @@ -29,18 +45,19 @@ describe('setup', () => { startTimer: jest.fn(), measureTime: jest.fn(() => 12), })); - jest.mock('../../../../src/server/utils/logging/logger', () => ({ info: jest.fn() })); - ({ monkeypatches } = require('@americanexpress/lumberjack')); ({ startTimer } = require('../../../../src/server/utils/logging/timing')); - logger = require('../../../../src/server/utils/logging/logger'); + logger = require('../../../../src/server/utils/logging/logger').default; require('../../../../src/server/utils/logging/setup'); + jest.spyOn(logger, 'info').mockImplementation(() => 0); } it('replaces the global console with logger', () => { load(); - expect(monkeypatches.replaceGlobalConsole).toHaveBeenCalledTimes(1); - expect(monkeypatches.replaceGlobalConsole).toHaveBeenCalledWith(logger); + logMethods.forEach((method) => { + expect(console[method].name).toBe('bound hookWrappedLog'); + expect(console[method]).not.toBe(originalConsole[method]); + }); }); it('spies on HTTP requests', () => { diff --git a/__tests__/server/utils/logging/development-formatters/utils.spec.js b/__tests__/server/utils/logging/utils.spec.js similarity index 97% rename from __tests__/server/utils/logging/development-formatters/utils.spec.js rename to __tests__/server/utils/logging/utils.spec.js index 9386faa94..802c05d00 100644 --- a/__tests__/server/utils/logging/development-formatters/utils.spec.js +++ b/__tests__/server/utils/logging/utils.spec.js @@ -19,7 +19,7 @@ import { printStatusCode, printStatusMessage, printDurationTime, -} from '../../../../../src/server/utils/logging/development-formatters/utils'; +} from '../../../../src/server/utils/logging/utils'; jest.mock('chalk'); diff --git a/__tests__/server/utils/onModuleLoad.spec.jsx b/__tests__/server/utils/onModuleLoad.spec.jsx index 6b85c064f..9bdb1e540 100644 --- a/__tests__/server/utils/onModuleLoad.spec.jsx +++ b/__tests__/server/utils/onModuleLoad.spec.jsx @@ -14,6 +14,7 @@ * permissions and limitations under the License. */ +import util from 'util'; import React from 'react'; import { preprocessEnvVar } from '@americanexpress/env-config-utils'; import { META_DATA_KEY } from '@americanexpress/one-app-bundler'; @@ -441,7 +442,7 @@ describe('onModuleLoad', () => { moduleName: 'some-root', }); expect(consoleInfoSpy).toHaveBeenCalledTimes(1); - expect(consoleInfoSpy).toHaveBeenCalledWith('Loaded module some-root@1.0.15'); + expect(util.format(...consoleInfoSpy.mock.calls[0])).toBe('Loaded module some-root@1.0.15'); }); it('logs when other modules are loaded', () => { @@ -450,7 +451,7 @@ describe('onModuleLoad', () => { moduleName: 'not-the-root-module', }); expect(consoleInfoSpy).toHaveBeenCalledTimes(1); - expect(consoleInfoSpy).toHaveBeenCalledWith('Loaded module not-the-root-module@1.0.16'); + expect(util.format(...consoleInfoSpy.mock.calls[0])).toBe('Loaded module not-the-root-module@1.0.16'); }); it('updates allowed safeRequest values from the root module', () => { diff --git a/__tests__/server/utils/pollModuleMap.spec.js b/__tests__/server/utils/pollModuleMap.spec.js index a08ccf8b4..2ef68aac3 100644 --- a/__tests__/server/utils/pollModuleMap.spec.js +++ b/__tests__/server/utils/pollModuleMap.spec.js @@ -13,6 +13,7 @@ * or implied. See the License for the specific language governing * permissions and limitations under the License. */ +import util from 'util'; jest.useFakeTimers(); jest.spyOn(global, 'setTimeout'); @@ -127,9 +128,13 @@ describe('pollModuleMap', () => { const { default: pollModuleMap } = load(); console.log // monitor setup - .mockImplementationOnce(() => { /* noop a few times */ }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) // pollModuleMap run 1 - .mockImplementationOnce(() => { throw new Error('STDOUT pipe closed unexpectedly'); }); + .mockImplementationOnce(() => { + throw new Error('STDOUT pipe closed unexpectedly'); + }); await pollModuleMap(); expect(setTimeout).toHaveBeenCalledTimes(1); @@ -140,15 +145,27 @@ describe('pollModuleMap', () => { const { default: pollModuleMap, MIN_POLL_TIME } = load(); console.log // monitor setup - .mockImplementationOnce(() => { /* noop a few times */ }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) // pollModuleMap run 1 - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) // pollModuleMap run 2 - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) // pollModuleMap run 3 - .mockImplementationOnce(() => { throw new Error('STDOUT pipe closed unexpectedly later on'); }); + .mockImplementationOnce(() => { + throw new Error('STDOUT pipe closed unexpectedly later on'); + }); await pollModuleMap(); expect(setTimeout).toHaveBeenCalledTimes(1); @@ -166,10 +183,17 @@ describe('pollModuleMap', () => { it('schedules a new poll after a polling error despite resetGauge throwing', async () => { const { default: pollModuleMap, MIN_POLL_TIME } = load(); - resetGauge.mockClear() - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { throw new Error('unable to increment gague'); }); + resetGauge + .mockClear() + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + throw new Error('unable to increment gague'); + }); await pollModuleMap(); expect(setTimeout).toHaveBeenCalledTimes(1); @@ -187,10 +211,17 @@ describe('pollModuleMap', () => { it('schedules a new poll after a polling error despite setGauge throwing', async () => { const { default: pollModuleMap, MIN_POLL_TIME } = load(); - setGauge.mockClear() - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { throw new Error('unable to increment gague'); }); + setGauge + .mockClear() + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + throw new Error('unable to increment gague'); + }); await pollModuleMap(); expect(setTimeout).toHaveBeenCalledTimes(1); @@ -224,8 +255,10 @@ describe('pollModuleMap', () => { expect(loadModules).toHaveBeenCalledTimes(1); expect(console.log).toHaveBeenCalledTimes(3); - expect(console.log.mock.calls[2][0]).toMatch(/^pollModuleMap: 1 modules loaded\/updated:$/); - expect(console.log.mock.calls[2][1]).toEqual(moduleMapUpdates); + expect(util.format(...console.log.mock.calls[2])).toMatchInlineSnapshot(` + "pollModuleMap: 1 modules loaded/updated: + { 'module-name': 'module-data-here' }" + `); expect(setTimeout).toHaveBeenCalledTimes(1); expect(setTimeout).toHaveBeenCalledWith(pollModuleMap, MIN_POLL_TIME); @@ -242,7 +275,7 @@ describe('pollModuleMap', () => { expect(loadModules).toHaveBeenCalledTimes(1); expect(console.log).toHaveBeenCalledTimes(3); - expect(console.log.mock.calls[2][0]).toMatch( + expect(util.format(...console.log.mock.calls[2])).toMatch( /^pollModuleMap: no updates, looking again in \d+s$/ ); @@ -279,12 +312,17 @@ describe('pollModuleMap', () => { it('resets the time to the next polling to the minimum if there were rejected modules', async () => { const { default: pollModuleMap, MIN_POLL_TIME } = load(); - loadModulesPromise = Promise.resolve({ rejectedModules: { 'bad-module': { reasonForRejection: 'not compatible' } } }); + loadModulesPromise = Promise.resolve({ + rejectedModules: { 'bad-module': { reasonForRejection: 'not compatible' } }, + }); await pollModuleMap(); expect(loadModules).toHaveBeenCalledTimes(1); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.warn).toHaveBeenCalledWith('pollModuleMap: 1 modules rejected:', ['bad-module: not compatible']); + expect(util.format(...console.warn.mock.calls[0])).toMatchInlineSnapshot(` + "pollModuleMap: 1 modules rejected: + [ 'bad-module: not compatible', [length]: 1 ]" + `); expect(setTimeout).toHaveBeenCalledTimes(1); // check that the poll interval is reset to min. @@ -299,7 +337,9 @@ describe('pollModuleMap', () => { it('schedules a new polling despite console.error throwing on the initial check', async () => { const { default: pollModuleMap } = load(); loadModulesPromise = Promise.reject(new Error('sample test error')); - console.error.mockImplementationOnce(() => { throw new Error('STDERR pipe closed unexpectedly'); }); + console.error.mockImplementationOnce(() => { + throw new Error('STDERR pipe closed unexpectedly'); + }); await pollModuleMap(); expect(setTimeout).toHaveBeenCalledTimes(1); @@ -308,9 +348,15 @@ describe('pollModuleMap', () => { it('schedules a new poll after a polling error despite console.error throwing', async () => { const { default: pollModuleMap } = load(); console.error - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { throw new Error('STDERR pipe closed unexpectedly'); }); + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + throw new Error('STDERR pipe closed unexpectedly'); + }); loadModulesPromise = Promise.reject(new Error('sample test error')); @@ -329,10 +375,17 @@ describe('pollModuleMap', () => { it('schedules a new poll after a polling error despite incrementGauge throwing', async () => { const { default: pollModuleMap } = load(); - incrementGauge.mockClear() - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { /* noop a few times */ }) - .mockImplementationOnce(() => { throw new Error('unable to increment gague'); }); + incrementGauge + .mockClear() + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + /* noop a few times */ + }) + .mockImplementationOnce(() => { + throw new Error('unable to increment gague'); + }); loadModulesPromise = Promise.reject(new Error('sample test error')); @@ -442,8 +495,8 @@ describe('pollModuleMap', () => { expect(setInterval).toHaveBeenCalledTimes(1); setInterval.mock.calls[0][0](); expect(console.log).toHaveBeenCalledTimes(2); - expect(console.log.mock.calls[0]).toMatchSnapshot(); - expect(console.log.mock.calls[1]).toMatchSnapshot(); + expect(util.format(...console.log.mock.calls[0])).toMatchSnapshot(); + expect(util.format(...console.log.mock.calls[1])).toMatchSnapshot(); }); it('logs when polling is considered stopped', async () => { @@ -460,8 +513,8 @@ describe('pollModuleMap', () => { expect(console.log).toHaveBeenCalledTimes(1); expect(console.log.mock.calls[0]).toMatchSnapshot(); expect(console.warn).toHaveBeenCalledTimes(2); - expect(console.warn.mock.calls[0]).toMatchSnapshot(); - expect(console.warn.mock.calls[1]).toMatchSnapshot(); + expect(util.format(...console.warn.mock.calls[0])).toMatchSnapshot(); + expect(util.format(...console.warn.mock.calls[1])).toMatchSnapshot(); }); }); }); diff --git a/__tests__/server/utils/redirectAllowList.spec.js b/__tests__/server/utils/redirectAllowList.spec.js index fc00fd76a..50bc2a856 100644 --- a/__tests__/server/utils/redirectAllowList.spec.js +++ b/__tests__/server/utils/redirectAllowList.spec.js @@ -1,11 +1,31 @@ +/* + * Copyright 2023 American Express Travel Related Services Company, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express + * or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ + +import util from 'util'; import { setRedirectAllowList, isRedirectUrlAllowed, getRedirectAllowList, } from '../../../src/server/utils/redirectAllowList'; +jest.spyOn(console, 'error').mockImplementation(() => {}); + describe('redirectAllowList', () => { beforeEach(() => { + jest.clearAllMocks(); setRedirectAllowList([]); }); describe('setRedirectAllowList', () => { @@ -15,16 +35,14 @@ describe('redirectAllowList', () => { expect(getRedirectAllowList()).toEqual(['https://americanexpress.com', 'https://*.example.com']); }); it('should log an error if allow list is not an array', () => { - jest.spyOn(console, 'error').mockImplementation(() => {}); const redirectAllowList = 'https://americanexpress.com'; setRedirectAllowList(redirectAllowList); expect(console.error).toBeCalledWith('redirectAllowList is not an array'); }); it('should log an error if allow list contains insecure protocol (http)', () => { - jest.spyOn(console, 'error').mockImplementation(() => {}); const redirectAllowList = ['http://americanexpress.com']; setRedirectAllowList(redirectAllowList); - expect(console.error).toBeCalledWith('Insecure protocols (http://) are not allowed to be redirect locations. Ignoring \'http://americanexpress.com\' listed in redirectAlowList configuration.'); + expect(util.format(...console.error.mock.calls[0])).toBe('Insecure protocols (http://) are not allowed to be redirect locations. Ignoring \'http://americanexpress.com\' listed in redirectAlowList configuration.'); }); }); describe('validateRedirectUrl', () => { diff --git a/__tests__/server/utils/safeRequest.spec.js b/__tests__/server/utils/safeRequest.spec.js index dfaf1069e..f46aab980 100644 --- a/__tests__/server/utils/safeRequest.spec.js +++ b/__tests__/server/utils/safeRequest.spec.js @@ -19,8 +19,6 @@ let extendRestrictedAttributesAllowList; let validateSafeRequestRestrictedAttributes; let getRequiredRestrictedAttributes; -jest.spyOn(console, 'error').mockImplementation(() => { }); - describe('safeRequest', () => { const dirtyRequest = { // makes sure defined falsy values get added too @@ -55,6 +53,8 @@ describe('safeRequest', () => { raw: { url: '/foo/bar.html', }, + + log: { error: jest.fn() }, }; function requireSafeRequest() { @@ -281,7 +281,7 @@ describe('safeRequest', () => { expect(cleanedBodyRequest).toHaveProperty('body'); expect(cleanedBodyRequest.body).toEqual('{ invalid }'); - expect(console.error).toHaveBeenCalledWith('request body cannot be parsed', '{ invalid }'); + expect(dirtyRequest.log.error).toHaveBeenCalledWith('request body cannot be parsed', '{ invalid }'); }); }); }); diff --git a/package-lock.json b/package-lock.json index 927a1d06a..84e99e9b5 100644 --- a/package-lock.json +++ b/package-lock.json @@ -34,6 +34,7 @@ "core-js": "^3.31.0", "create-shared-react-context": "^1.0.5", "cross-fetch": "^4.0.0", + "deepmerge": "^4.3.1", "fastify": "^4.18.0", "fastify-metrics": "^10.3.0", "fastify-plugin": "^4.2.0", @@ -49,6 +50,7 @@ "opossum": "^7.1.0", "opossum-prometheus": "^0.3.0", "pidusage": "^3.0.2", + "pino": "^8.14.1", "prom-client": "^14.2.0", "prop-types": "^15.8.1", "react": "^17.0.2", @@ -113,8 +115,8 @@ "node-fetch": "^2.6.7", "node-mocks-http": "^1.11.0", "nodemon": "^2.0.20", - "ora": "^5.4.1", "parse-prometheus-text-format": "^1.1.1", + "pino-pretty": "^10.1.0", "prettier": "^2.7.1", "proxy-agent": "^5.0.0", "react-test-renderer": "^17.0.2", @@ -8274,30 +8276,6 @@ "node": ">=6" } }, - "node_modules/cli-cursor": { - "version": "3.1.0", - "resolved": "https://registry.npmjs.org/cli-cursor/-/cli-cursor-3.1.0.tgz", - "integrity": "sha512-I/zHAwsKf9FqGoXM4WWRACob9+SNukZTd94DWF57E4toouRulbCxcUh6RKUEOQlYTHJnzkPMySvPNaaSLNfLZw==", - "dev": true, - "dependencies": { - "restore-cursor": "^3.1.0" - }, - "engines": { - "node": ">=8" - } - }, - "node_modules/cli-spinners": { - "version": "2.7.0", - "resolved": "https://registry.npmjs.org/cli-spinners/-/cli-spinners-2.7.0.tgz", - "integrity": "sha512-qu3pN8Y3qHNgE2AFweciB1IfMnmZ/fsNTEE+NOFjmGB2F/7rLhnhzppvpCnN4FovtP26k8lHyy9ptEbNwWFLzw==", - "dev": true, - "engines": { - "node": ">=6" - }, - "funding": { - "url": "https://github.com/sponsors/sindresorhus" - } - }, "node_modules/cliui": { "version": "8.0.1", "resolved": "https://registry.npmjs.org/cliui/-/cliui-8.0.1.tgz", @@ -8322,15 +8300,6 @@ "node": ">=8" } }, - "node_modules/clone": { - "version": "1.0.4", - "resolved": "https://registry.npmjs.org/clone/-/clone-1.0.4.tgz", - "integrity": "sha512-JQHZ2QMW6l3aH/j6xCqQThY/9OH4D/9ls34cgkUBiEeocRTU04tHfKPBsUK1PqZCUQM7GiA0IIXJSuXHI64Kbg==", - "dev": true, - "engines": { - "node": ">=0.8" - } - }, "node_modules/clone-deep": { "version": "4.0.1", "resolved": "https://registry.npmjs.org/clone-deep/-/clone-deep-4.0.1.tgz", @@ -8416,6 +8385,12 @@ "resolved": "https://registry.npmjs.org/colord/-/colord-2.9.3.tgz", "integrity": "sha512-jeC1axXpnb0/2nn/Y1LPuLdgXBLH7aDcHu4KEKfqw3CUhX7ZpfBSlPKyqXE6btIgEzfWtrX3/tyBCaCvXvMkOw==" }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "dev": true + }, "node_modules/colors": { "version": "1.4.0", "resolved": "https://registry.npmjs.org/colors/-/colors-1.4.0.tgz", @@ -9980,26 +9955,13 @@ "integrity": "sha512-oIPzksmTg4/MriiaYGO+okXDT7ztn/w3Eptv/+gSIdMdKsJo0u4CfYNFJPy+4SKMuCqGw2wxnA+URMg3t8a/bQ==" }, "node_modules/deepmerge": { - "version": "4.3.0", - "resolved": "https://registry.npmjs.org/deepmerge/-/deepmerge-4.3.0.tgz", - "integrity": "sha512-z2wJZXrmeHdvYJp/Ux55wIjqo81G5Bp4c+oELTW+7ar6SogWHajt5a9gO3s3IDaGSAXjDk0vlQKN3rms8ab3og==", - "dev": true, + "version": "4.3.1", + "resolved": "https://registry.npmjs.org/deepmerge/-/deepmerge-4.3.1.tgz", + "integrity": "sha512-3sUqbMEc77XqpdNO7FRyRog+eW3ph+GYCbj+rK+uYyRMuwsVy0rMiVtPn+QJlKFvWP/1PYpapqYn0Me2knFn+A==", "engines": { "node": ">=0.10.0" } }, - "node_modules/defaults": { - "version": "1.0.4", - "resolved": "https://registry.npmjs.org/defaults/-/defaults-1.0.4.tgz", - "integrity": "sha512-eFuaLoy/Rxalv2kr+lqMlUnrDWV+3j4pljOIJgLIhI058IQfWJ7vXhyEIHu+HtC738klGALYxOKDO0bQP3tg8A==", - "dev": true, - "dependencies": { - "clone": "^1.0.2" - }, - "funding": { - "url": "https://github.com/sponsors/sindresorhus" - } - }, "node_modules/defer-to-connect": { "version": "2.0.1", "resolved": "https://registry.npmjs.org/defer-to-connect/-/defer-to-connect-2.0.1.tgz", @@ -12680,6 +12642,12 @@ "resolved": "https://registry.npmjs.org/fast-content-type-parse/-/fast-content-type-parse-1.0.0.tgz", "integrity": "sha512-Xbc4XcysUXcsP5aHUU7Nq3OwvHq97C+WnbkeIefpeYLX+ryzFJlU6OStFJhs6Ol0LkUGpcK+wL0JwfM+FCU5IA==" }, + "node_modules/fast-copy": { + "version": "3.0.1", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-3.0.1.tgz", + "integrity": "sha512-Knr7NOtK3HWRYGtHoJrjkaWepqT8thIVGAwt0p0aUs1zqkAzXZV4vo9fFNwyb5fcqK1GKYFYxldQdIDVKhUAfA==", + "dev": true + }, "node_modules/fast-decode-uri-component": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/fast-decode-uri-component/-/fast-decode-uri-component-1.0.1.tgz", @@ -14284,6 +14252,70 @@ "node": ">=16.0.0" } }, + "node_modules/help-me": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-4.2.0.tgz", + "integrity": "sha512-TAOnTB8Tz5Dw8penUuzHVrKNKlCIbwwbHnXraNJxPwf8LRtE2HlM84RYuezMFcwOJmoYOCWVDyJ8TQGxn9PgxA==", + "dev": true, + "dependencies": { + "glob": "^8.0.0", + "readable-stream": "^3.6.0" + } + }, + "node_modules/help-me/node_modules/brace-expansion": { + "version": "2.0.1", + "resolved": "https://registry.npmjs.org/brace-expansion/-/brace-expansion-2.0.1.tgz", + "integrity": "sha512-XnAIvQ8eM+kC6aULx6wuQiwVsnzsi9d3WxzV3FpWTGA19F621kwdbsAcFKXgKUHZWsy+mY6iL1sHTxWEFCytDA==", + "dev": true, + "dependencies": { + "balanced-match": "^1.0.0" + } + }, + "node_modules/help-me/node_modules/glob": { + "version": "8.1.0", + "resolved": "https://registry.npmjs.org/glob/-/glob-8.1.0.tgz", + "integrity": "sha512-r8hpEjiQEYlF2QU0df3dS+nxxSIreXQS1qRhMJM0Q5NDdR386C7jb7Hwwod8Fgiuex+k0GFjgft18yvxm5XoCQ==", + "dev": true, + "dependencies": { + "fs.realpath": "^1.0.0", + "inflight": "^1.0.4", + "inherits": "2", + "minimatch": "^5.0.1", + "once": "^1.3.0" + }, + "engines": { + "node": ">=12" + }, + "funding": { + "url": "https://github.com/sponsors/isaacs" + } + }, + "node_modules/help-me/node_modules/minimatch": { + "version": "5.1.6", + "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-5.1.6.tgz", + "integrity": "sha512-lKwV/1brpG6mBUFHtb7NUmtABCb2WZZmm2wNiOA5hAb8VdCS4B3dtMWyvcoViccwAW/COERjXLt0zP1zXUN26g==", + "dev": true, + "dependencies": { + "brace-expansion": "^2.0.1" + }, + "engines": { + "node": ">=10" + } + }, + "node_modules/help-me/node_modules/readable-stream": { + "version": "3.6.2", + "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-3.6.2.tgz", + "integrity": "sha512-9u/sniCrY3D5WdsERHzHE4G2YCXqoG5FTHUiCC4SIbr6XcLZBY05ya9EKjYek9O5xOAwjGq+1JdGBAS7Q9ScoA==", + "dev": true, + "dependencies": { + "inherits": "^2.0.3", + "string_decoder": "^1.1.1", + "util-deprecate": "^1.0.1" + }, + "engines": { + "node": ">= 6" + } + }, "node_modules/hexoid": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/hexoid/-/hexoid-1.0.0.tgz", @@ -15371,15 +15403,6 @@ "url": "https://github.com/sponsors/wooorm" } }, - "node_modules/is-interactive": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/is-interactive/-/is-interactive-1.0.0.tgz", - "integrity": "sha512-2HvIEKRoqS62guEC+qBjpvRubdX910WCMuJTZ+I9yvqKU2/12eSL549HMwtabb4oupdj2sMP50k+XJfB/8JE6w==", - "dev": true, - "engines": { - "node": ">=8" - } - }, "node_modules/is-map": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/is-map/-/is-map-2.0.2.tgz", @@ -15568,18 +15591,6 @@ "url": "https://github.com/sponsors/ljharb" } }, - "node_modules/is-unicode-supported": { - "version": "0.1.0", - "resolved": "https://registry.npmjs.org/is-unicode-supported/-/is-unicode-supported-0.1.0.tgz", - "integrity": "sha512-knxG2q4UC3u8stRGyAVJCOdxFmv5DZiRcdlIaAQXAbSfJya+OhopNotLQrstBhququ4ZpuKbDc/8S6mgXgPFPw==", - "dev": true, - "engines": { - "node": ">=10" - }, - "funding": { - "url": "https://github.com/sponsors/sindresorhus" - } - }, "node_modules/is-weakmap": { "version": "2.0.1", "resolved": "https://registry.npmjs.org/is-weakmap/-/is-weakmap-2.0.1.tgz", @@ -17504,6 +17515,15 @@ "@sideway/pinpoint": "^2.0.0" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "dev": true, + "engines": { + "node": ">=10" + } + }, "node_modules/js-cookie": { "version": "2.2.1", "resolved": "https://registry.npmjs.org/js-cookie/-/js-cookie-2.2.1.tgz", @@ -18253,22 +18273,6 @@ "integrity": "sha512-C7IOaBBK/0gMORRBd8OETNx3kmOkgIWIPvyDpZSCTwUrpYmgZwJkjZeOD8ww4xbOUOs4/attY+pciKvadNfFbg==", "dev": true }, - "node_modules/log-symbols": { - "version": "4.1.0", - "resolved": "https://registry.npmjs.org/log-symbols/-/log-symbols-4.1.0.tgz", - "integrity": "sha512-8XPvpAA8uyhfteu8pIvQxpJZ7SYYdpUivZpGy6sFsBuKRY/7rQGavedeB8aK+Zkyq6upMFVL/9AW6vOYzfRyLg==", - "dev": true, - "dependencies": { - "chalk": "^4.1.0", - "is-unicode-supported": "^0.1.0" - }, - "engines": { - "node": ">=10" - }, - "funding": { - "url": "https://github.com/sponsors/sindresorhus" - } - }, "node_modules/loglevel": { "version": "1.8.1", "resolved": "https://registry.npmjs.org/loglevel/-/loglevel-1.8.1.tgz", @@ -19802,41 +19806,6 @@ "node": ">= 0.8.0" } }, - "node_modules/ora": { - "version": "5.4.1", - "resolved": "https://registry.npmjs.org/ora/-/ora-5.4.1.tgz", - "integrity": "sha512-5b6Y85tPxZZ7QytO+BQzysW31HJku27cRIlkbAXaNx+BdcVi+LlRFmVXzeF6a7JCwJpyw5c4b+YSVImQIrBpuQ==", - "dev": true, - "dependencies": { - "bl": "^4.1.0", - "chalk": "^4.1.0", - "cli-cursor": "^3.1.0", - "cli-spinners": "^2.5.0", - "is-interactive": "^1.0.0", - "is-unicode-supported": "^0.1.0", - "log-symbols": "^4.1.0", - "strip-ansi": "^6.0.0", - "wcwidth": "^1.0.1" - }, - "engines": { - "node": ">=10" - }, - "funding": { - "url": "https://github.com/sponsors/sindresorhus" - } - }, - "node_modules/ora/node_modules/strip-ansi": { - "version": "6.0.1", - "resolved": "https://registry.npmjs.org/strip-ansi/-/strip-ansi-6.0.1.tgz", - "integrity": "sha512-Y38VPSHcqkFrCpFnQ9vuSXmquuv5oXOKpGeT6aGrr3o3Gc9AlVa6JBfUSOCnbxGGZF+/0ooI7KrPuUSztUdU5A==", - "dev": true, - "dependencies": { - "ansi-regex": "^5.0.1" - }, - "engines": { - "node": ">=8" - } - }, "node_modules/os-browserify": { "version": "0.3.0", "resolved": "https://registry.npmjs.org/os-browserify/-/os-browserify-0.3.0.tgz", @@ -20401,6 +20370,40 @@ "node": ">= 10.x" } }, + "node_modules/pino-pretty": { + "version": "10.1.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-10.1.0.tgz", + "integrity": "sha512-9gAgVHCVTEq0ThcjoXkOICYQgdqh1h90WSuVAnNeCrRrefJInUvMbpDfy6PlsI29Nbu9UW9CGkUHztrR1A9N+A==", + "dev": true, + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^3.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^4.0.1", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^1.0.0", + "pump": "^3.0.0", + "readable-stream": "^4.0.0", + "secure-json-parse": "^2.4.0", + "sonic-boom": "^3.0.0", + "strip-json-comments": "^3.1.1" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "dev": true, + "engines": { + "node": "*" + } + }, "node_modules/pino-std-serializers": { "version": "6.2.1", "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-6.2.1.tgz", @@ -22752,19 +22755,6 @@ "integrity": "sha512-bCK/2Z4zLidyB4ReuIsvALH6w31YfAQDmXMqMx6FyfHqvBxtjC0eRumeSu4Bs3XtXwpyIywtSTrVT99BxY1f9w==", "dev": true }, - "node_modules/restore-cursor": { - "version": "3.1.0", - "resolved": "https://registry.npmjs.org/restore-cursor/-/restore-cursor-3.1.0.tgz", - "integrity": "sha512-l+sSefzHpj5qimhFSE5a8nufZYAM3sBSVMAPtYkmC+4EH2anSGaEMXSD0izRQbu9nfyQ9y5JrVmp7E8oZrUjvA==", - "dev": true, - "dependencies": { - "onetime": "^5.1.0", - "signal-exit": "^3.0.2" - }, - "engines": { - "node": ">=8" - } - }, "node_modules/ret": { "version": "0.2.2", "resolved": "https://registry.npmjs.org/ret/-/ret-0.2.2.tgz", @@ -26421,15 +26411,6 @@ "node": ">=0.10.0" } }, - "node_modules/wcwidth": { - "version": "1.0.1", - "resolved": "https://registry.npmjs.org/wcwidth/-/wcwidth-1.0.1.tgz", - "integrity": "sha512-XHPEwS0q6TaxcvG85+8EYkbiCux2XtWG2mkc47Ng2A77BQu9+DqIOJldST4HgPkuea7dvKSj5VgX3P1d4rW8Tg==", - "dev": true, - "dependencies": { - "defaults": "^1.0.3" - } - }, "node_modules/webdriver": { "version": "7.30.0", "resolved": "https://registry.npmjs.org/webdriver/-/webdriver-7.30.0.tgz", diff --git a/package.json b/package.json index e4d941e40..766f92912 100644 --- a/package.json +++ b/package.json @@ -105,6 +105,7 @@ "core-js": "^3.31.0", "create-shared-react-context": "^1.0.5", "cross-fetch": "^4.0.0", + "deepmerge": "^4.3.1", "fastify": "^4.18.0", "fastify-metrics": "^10.3.0", "fastify-plugin": "^4.2.0", @@ -120,6 +121,7 @@ "opossum": "^7.1.0", "opossum-prometheus": "^0.3.0", "pidusage": "^3.0.2", + "pino": "^8.14.1", "prom-client": "^14.2.0", "prop-types": "^15.8.1", "react": "^17.0.2", @@ -184,8 +186,8 @@ "node-fetch": "^2.6.7", "node-mocks-http": "^1.11.0", "nodemon": "^2.0.20", - "ora": "^5.4.1", "parse-prometheus-text-format": "^1.1.1", + "pino-pretty": "^10.1.0", "prettier": "^2.7.1", "proxy-agent": "^5.0.0", "react-test-renderer": "^17.0.2", diff --git a/scripts/watch-server.js b/scripts/watch-server.js index 443609826..71b947b26 100644 --- a/scripts/watch-server.js +++ b/scripts/watch-server.js @@ -43,10 +43,12 @@ const buildServiceWorkerScripts = require('./build-service-workers'); }); const flags = process.argv.filter((arg) => [ - '--root-module-name', + '--log-format', + '--log-level', '--module-map-url', - '--use-middleware', + '--root-module-name', '--use-host', + '--use-middleware', ].find((argName) => arg.startsWith(argName))); const nodemon = spawn('nodemon', [ diff --git a/src/server/config/env/argv.js b/src/server/config/env/argv.js index 9f7568648..cab501942 100644 --- a/src/server/config/env/argv.js +++ b/src/server/config/env/argv.js @@ -83,7 +83,7 @@ yargs .option('log-level', { describe: 'Lowest level of log entries to show', type: 'string', - choices: ['error', 'warn', 'log', 'info'], + choices: ['error', 'warn', 'log', 'info', 'trace'], default: process.env.NODE_ENV === 'development' ? 'log' : 'info', }); diff --git a/src/server/index.js b/src/server/index.js index 1d30f6a57..75168b6cf 100644 --- a/src/server/index.js +++ b/src/server/index.js @@ -56,13 +56,13 @@ export const listen = async ({ port, }); - console.log(`${context} listening on port ${port}`); + console.log('%s listening on port %d', context, port); addServer(instance); return instance; } catch (error) { - console.error(`Error encountered starting ${context}`, error); + console.error('Error encountered starting %s', context, error); throw error; } }; @@ -129,7 +129,7 @@ async function oneAppDevProxyStart() { if (err) { rej(err); } else { - console.log(`👖 one-app-dev-proxy server listening on port ${oneAppDevProxyPort}`); + console.log('👖 one-app-dev-proxy server listening on port %d', oneAppDevProxyPort); res(); } })); diff --git a/src/server/metricsServer.js b/src/server/metricsServer.js index b6a15e50d..81300b132 100644 --- a/src/server/metricsServer.js +++ b/src/server/metricsServer.js @@ -20,12 +20,13 @@ import rateLimit from '@fastify/rate-limit'; import { register as metricsRegister, collectDefaultMetrics } from 'prom-client'; import logging from './utils/logging/fastifyPlugin'; +import logger from './utils/logging/logger'; import healthCheck from './plugins/healthCheck'; collectDefaultMetrics(); export async function createMetricsServer() { - const fastify = Fastify(); + const fastify = Fastify({ logger, disableRequestLogging: true }); await fastify.register(rateLimit, { max: 120, diff --git a/src/server/plugins/reactHtml/createRequestHtmlFragment.jsx b/src/server/plugins/reactHtml/createRequestHtmlFragment.jsx index 0a93925f4..c9c7a2336 100644 --- a/src/server/plugins/reactHtml/createRequestHtmlFragment.jsx +++ b/src/server/plugins/reactHtml/createRequestHtmlFragment.jsx @@ -14,8 +14,6 @@ * permissions and limitations under the License. */ -import util from 'util'; - import React from 'react'; import { Provider } from 'react-redux'; import url, { Url } from 'url'; @@ -153,7 +151,7 @@ const createRequestHtmlFragment = async (request, reply, { createRoutes }) => { request.helmetInfo = helmetInfo; } } catch (err) { - console.error(util.format('error creating request HTML fragment for %s', request.url), err); + request.log.error('error creating request HTML fragment for %s', request.url, err); } }; diff --git a/src/server/plugins/reactHtml/createRequestStore.js b/src/server/plugins/reactHtml/createRequestStore.js index f4596ced7..698159e40 100644 --- a/src/server/plugins/reactHtml/createRequestStore.js +++ b/src/server/plugins/reactHtml/createRequestStore.js @@ -68,7 +68,7 @@ const createRequestStore = ( request.store = store; // eslint-disable-line no-param-reassign request.clientModuleMapCache = getClientModuleMapCache(); } catch (err) { - console.error('error creating store for request', err); + request.log.error('error creating store for request', err); renderStaticErrorPage(request, reply); } }; diff --git a/src/server/plugins/reactHtml/index.jsx b/src/server/plugins/reactHtml/index.jsx index 2a0fe983d..24761ac6f 100644 --- a/src/server/plugins/reactHtml/index.jsx +++ b/src/server/plugins/reactHtml/index.jsx @@ -94,12 +94,12 @@ export function renderModuleScripts({ }).join(isDevelopmentEnv ? '\n ' : ''); } -function serializeClientInitialState(clientInitialState) { +function serializeClientInitialState(clientInitialState, request) { // try to build the full state, this _might_ fail (ex: 'Error serializing unrecognized object') try { return transit.toJSON(clientInitialState); } catch (err) { - console.error('encountered an error serializing full client initial state', err); + request.log.error('encountered an error serializing full client initial state', err); // clear out an internal cache that corrupts the serialization generated on the next call // TODO: understand transit-js and transit-immutable-js internals to properly fix the bug @@ -118,7 +118,7 @@ function serializeClientInitialState(clientInitialState) { } catch (err) { transit.toJSON('clear out an internal cache, again'); // something is really wrong - console.error('unable to build the most basic initial state for a client to startup', err); + request.log.error('unable to build the most basic initial state for a client to startup', err); throw err; } } @@ -186,6 +186,7 @@ export function getBody({ clientModuleMapCache, scriptNonce, pwaMetadata, + request, }) { const bundle = isLegacy ? 'legacyBrowser' : 'browser'; const { bodyAttributes, script } = helmetInfo; @@ -197,7 +198,7 @@ export function getBody({