Switch to Fastify logger

__tests__/server/config/env/__snapshots__/argv.spec.js.snap

@@ -67,8 +67,9 @@ exports[`argv config has development options and defaults 6`] = `
       "warn",
       "log",
       "info",
+      "trace",
     ],
-    "default": "log",
+    "default": "info",
     "describe": "Lowest level of log entries to show",
     "type": "string",
   },
@@ -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",

__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',

__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 () => {

__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);
   });
 

__tests__/server/plugins/reactHtml/index.spec.jsx

@@ -34,6 +34,8 @@ 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.mock('react-helmet');
 
 jest.mock('../../../../src/server/utils/redirectAllowList', () => ({
@@ -141,11 +143,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 +256,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 +292,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 +317,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 +438,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 +448,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 +602,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 +838,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 +866,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);
@@ -1042,7 +1036,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>');

__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);
       });
     });