feat(logging): switch to fastify logger (#1084)

americanexpress · Sep 5, 2023 · 33fa971 · 33fa971
1 parent a6ecda7
commit 33fa971
Show file tree

Hide file tree

Showing 66 changed files with 1,534 additions and 2,246 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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('<!DOCTYPE html>');
@@ -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('<!DOCTYPE html>');
@@ -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('<!DOCTYPE html>');
       expect(reply.send.mock.calls[0][0]).toContain('<meta name="application-name" content="one-app">');
@@ -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('<!DOCTYPE html>');
       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('<!DOCTYPE html>');
@@ -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('<!DOCTYPE html>');

diff --git 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', () => {