perf(logger): defer execution of expensive logging calls (#614)

Author: H4ad

.eslintrc.js

@@ -5,6 +5,7 @@ module.exports = {
     expect: true,
     describe: true,
     beforeEach: true,
+    afterEach: true,
     jest: true
   }
 }

__tests__/integration.js

@@ -4,6 +4,7 @@ const express = require('express')
 const bodyParser = require('body-parser')
 const ejs = require('ejs').__express
 const serverlessExpress = require('../src/index')
+const serverlessExpressLogger = require('../src/logger')
 const {
   makeEvent,
   makeResponse,
@@ -467,39 +468,75 @@ describe.each(EACH_MATRIX)('%s:%s: integration tests', (eventSourceName, framewo
     expect(response).toEqual(expectedResponse)
   })
 
-  test('custom logger', async () => {
-    app = express()
-    router = express.Router()
-    app.use('/', router)
-    router.get('/users', (req, res) => {
-      res.json({})
+  describe('logger', () => {
+    const mocks = []
+
+    beforeEach(() => {
+      const mockMethods = [
+        'error',
+        'info',
+        'warn',
+        'log',
+        'debug'
+      ]
+
+      for (const method of mockMethods) { mocks.push(jest.spyOn(global.console, method).mockImplementation()) }
     })
-    const event = makeEvent({
-      eventSourceName,
-      path: '/users',
-      httpMethod: 'GET'
+
+    afterEach(() => {
+      for (const mock of mocks) mock.mockRestore()
     })
-    const customLogger = {
-      error: jest.fn(),
-      warn: jest.fn(),
-      info: jest.fn(),
-      verbose: jest.fn(),
-      debug: jest.fn()
-    }
-    serverlessExpressInstance = serverlessExpress({ app, log: customLogger })
-    await serverlessExpressInstance(event)
 
-    expect(customLogger.debug.mock.calls.length).toBe(6)
+    test('custom logger', async () => {
+      app = express()
+      router = express.Router()
+      app.use('/', router)
+      router.get('/users', (req, res) => {
+        res.json({})
+      })
+      const event = makeEvent({
+        eventSourceName,
+        path: '/users',
+        httpMethod: 'GET'
+      })
+      const customLogger = {
+        error: jest.fn(),
+        warn: jest.fn(),
+        info: jest.fn(),
+        verbose: jest.fn(),
+        debug: jest.fn()
+      }
+      serverlessExpressInstance = serverlessExpress({ app, log: customLogger })
+      await serverlessExpressInstance(event)
+
+      expect(customLogger.debug.mock.calls.length).toBe(6)
 
-    // TODO: test log levels
-    // customLogger.level = 'error'
-    // customLogger.debug.mockClear()
-    // customLogger.debug.mockReset()
-    // customLogger.debug = jest.fn()
+      // TODO: test log levels
+      // customLogger.level = 'error'
+      // customLogger.debug.mockClear()
+      // customLogger.debug.mockReset()
+      // customLogger.debug = jest.fn()
 
-    // serverlessExpressInstance = serverlessExpress({ app, log: customLogger })
-    // await serverlessExpressInstance(event)
-    // expect(customLogger.debug.mock.calls.length).toBe(0)
+      // serverlessExpressInstance = serverlessExpress({ app, log: customLogger })
+      // await serverlessExpressInstance(event)
+      // expect(customLogger.debug.mock.calls.length).toBe(0)
+    })
+
+    test('lazy print of logger', async () => {
+      const logger = serverlessExpressLogger()
+
+      logger.debug('debug', () => '=true', ' works')
+      logger.debug(() => 'debug')
+
+      expect(global.console.debug).not.toHaveBeenNthCalledWith(
+        1,
+        'debug=true works'
+      )
+      expect(global.console.debug).not.toHaveBeenNthCalledWith(
+        2,
+        'debug'
+      )
+    })
   })
 
   test('legacy/deprecated createServer', async () => {

src/configure.js

@@ -43,14 +43,14 @@ function configure ({
     log = configureLog,
     respondWithErrors = configureRespondWithErrors
   }) {
-    log.debug('SERVERLESS_EXPRESS:PROXY', {
+    log.debug('SERVERLESS_EXPRESS:PROXY', () => ({
       event: util.inspect(event, { depth: null }),
       context: util.inspect(context, { depth: null }),
       resolutionMode,
       eventSourceName,
       binarySettings,
       respondWithErrors
-    })
+    }))
 
     if (binaryMimeTypes) {
       console.warn('[DEPRECATION NOTICE] { binaryMimeTypes: [] } is deprecated. base64 encoding is now automatically determined based on response content-type and content-encoding. If you need to manually set binary content types, instead, use { binarySettings: { contentTypes: [] } }')

src/logger.js

@@ -1,40 +1,46 @@
+const lazyPrint = (value) => {
+  if (typeof value === 'function') { return value() }
+
+  return value
+}
+
 function logger ({
   level = 'error'
 } = {}) {
   return {
-    error (message, additional) {
+    error (message, ...additional) {
       if (!level.includes('debug', 'verbose', 'info', 'warn', 'error')) return
       console.error({
-        message,
-        ...additional
+        message: lazyPrint(message),
+        ...additional.map(lazyPrint)
       })
     },
-    warn (message, additional) {
+    warn (message, ...additional) {
       if (!level.includes('debug', 'verbose', 'info', 'warn')) return
       console.warn({
-        message,
-        ...additional
+        message: lazyPrint(message),
+        ...additional.map(lazyPrint)
       })
     },
     info (message, additional) {
       if (!level.includes('debug', 'verbose', 'info')) return
       console.info({
-        message,
-        ...additional
+        message: lazyPrint(message),
+        ...additional.map(lazyPrint)
       })
     },
     verbose (message, additional) {
       if (!level.includes('debug', 'verbose')) return
       console.debug({
-        message,
-        ...additional
+        message: lazyPrint(message),
+        ...additional.map(lazyPrint)
       })
     },
     debug (message, additional) {
       if (level !== 'debug') return
       console.debug({
-        message,
-        ...additional
+        message: lazyPrint(message),
+        ...additional.map(lazyPrint)
       })
     }
   }

src/transport.js

@@ -39,10 +39,10 @@ function forwardResponse ({
     response
   })
 
-  log.debug('SERVERLESS_EXPRESS:FORWARD_RESPONSE:EVENT_SOURCE_RESPONSE', {
+  log.debug('SERVERLESS_EXPRESS:FORWARD_RESPONSE:EVENT_SOURCE_RESPONSE', () => ({
     successResponse: util.inspect(successResponse, { depth: null }),
     body: logBody
-  })
+  }))
 
   resolver.succeed({
     response: successResponse