Companion improve logging (#3103)

* reorder code to fix lint warning

* Improve logging

When logging an object it would print [object Object] if `color` was set.
e.g.: google drive callback: "callback.oauth.resp [object Object]"
Now we will instead use util.inspect before calling color
Also fix some linting warnings

* Only util.inspect if not already string

this fixes tests
also simplify masking logic (only need to mask once)

* add test for object log masking

also simplify tests (reuse logic)

packages/@uppy/companion/src/server/logger.js

@@ -1,5 +1,6 @@
 const chalk = require('chalk')
 const escapeStringRegexp = require('escape-string-regexp')
+const util = require('util')
 
 const valuesToMask = []
 /**
@@ -16,6 +17,57 @@ exports.setMaskables = (maskables) => {
   Object.freeze(valuesToMask)
 }
 
+/**
+ * Mask the secret content of a message
+ *
+ * @param {string} msg the message whose content should be masked
+ * @returns {string}
+ */
+function maskMessage (msg) {
+  let out = msg
+  for (const toBeMasked of valuesToMask) {
+    const toBeReplaced = new RegExp(toBeMasked, 'gi')
+    out = out.replace(toBeReplaced, '******')
+  }
+  return out
+}
+
+/**
+ * message log
+ *
+ * @param {string | Error} msg the message to log
+ * @param {string} tag a unique tag to easily search for this message
+ * @param {string} level error | info | debug
+ * @param {string=} id a unique id to easily trace logs tied to a request
+ * @param {Function=} color function to display the log in appropriate color
+ * @param {boolean=} shouldLogStackTrace when set to true, errors will be logged with their stack trace
+ */
+const log = (msg, tag = '', level, id = '', color = (message) => message, shouldLogStackTrace) => {
+  const time = new Date().toISOString()
+  const whitespace = tag && id ? ' ' : ''
+
+  function logMsg (msg2) {
+    let msgString = typeof msg2 === 'string' ? msg2 : util.inspect(msg2)
+    msgString = maskMessage(msgString)
+    // eslint-disable-next-line no-console
+    console.log(color(`companion: ${time} [${level}] ${id}${whitespace}${tag}`), color(msgString))
+  }
+
+  if (msg instanceof Error) {
+    // Not sure why it only logs the stack without the message, but this is how the code was originally
+    if (shouldLogStackTrace && typeof msg.stack === 'string') {
+      logMsg(msg.stack)
+      return
+    }
+
+    // We don't want to log stack trace (this is how the code was originally)
+    logMsg(String(msg))
+    return
+  }
+
+  logMsg(msg)
+}
+
 /**
  * INFO level log
  *
@@ -66,52 +118,3 @@ exports.debug = (msg, tag, traceId) => {
     log(msg, tag, 'debug', traceId, chalk.bold.blue)
   }
 }
-
-/**
- * message log
- *
- * @param {string | Error} msg the message to log
- * @param {string} tag a unique tag to easily search for this message
- * @param {string} level error | info | debug
- * @param {Function=} color function to display the log in appropriate color
- * @param {string=} id a unique id to easily trace logs tied to a request
- * @param {boolean=} shouldLogStackTrace when set to true, errors will be logged with their stack trace
- */
-const log = (msg, tag, level, id, color, shouldLogStackTrace) => {
-  const time = new Date().toISOString()
-  tag = tag || ''
-  id = id || ''
-  const whitespace = tag && id ? ' ' : ''
-  color = color || ((message) => message)
-  if (typeof msg === 'string') {
-    msg = maskMessage(msg)
-  } else if (msg && typeof msg.message === 'string') {
-    msg.message = maskMessage(msg.message)
-  }
-
-  if (shouldLogStackTrace && msg instanceof Error && typeof msg.stack === 'string') {
-    msg.stack = maskMessage(msg.stack)
-    // exclude msg from template string so values such as error objects
-    // can be well formatted
-    console.log(color(`companion: ${time} [${level}] ${id}${whitespace}${tag}`), color(msg.stack))
-    return
-  }
-
-  // exclude msg from template string so values such as error objects
-  // can be well formatted
-  console.log(color(`companion: ${time} [${level}] ${id}${whitespace}${tag}`), color(msg))
-}
-
-/**
- * Mask the secret content of a message
- *
- * @param {string} msg the message whose content should be masked
- * @returns {string}
- */
-const maskMessage = (msg) => {
-  for (const toBeMasked of valuesToMask) {
-    const toBeReplaced = new RegExp(toBeMasked, 'gi')
-    msg = msg.replace(toBeReplaced, '******')
-  }
-  return msg
-}

packages/@uppy/companion/test/__tests__/logger.js

@@ -2,24 +2,36 @@
 const chalk = require('chalk')
 const logger = require('../../src/server/logger')
 
-describe('Test Logger secret mask', () => {
-  beforeAll(() => {
-    logger.setMaskables(['ToBeMasked1', 'toBeMasked2', 'toBeMasked(And)?Escaped'])
-  })
+const maskables = ['ToBeMasked1', 'toBeMasked2', 'toBeMasked(And)?Escaped']
 
-  test('masks secret values present in log.info messages', () => {
-    let loggedMessage = null
+function captureConsoleLog (log) {
+  let loggedMessage = null
+
+  // override the default console.log to capture the logged message
+  const defaultConsoleLog = console.log
 
-    // override the default console.log to capture the logged message
-    const defaultConsoleLog = console.log
+  try {
     console.log = (logPrefix, message) => {
       loggedMessage = message
       defaultConsoleLog(logPrefix, message)
     }
-
-    logger.info('this info has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
+  } finally {
+    log()
     // restore the default console.log before using "expect" to avoid weird log behaviors
     console.log = defaultConsoleLog
+  }
+  return loggedMessage
+}
+
+describe('Test Logger secret mask', () => {
+  beforeAll(() => {
+    logger.setMaskables(maskables)
+  })
+
+  test('masks secret values present in log.info messages', () => {
+    const loggedMessage = captureConsoleLog(() => {
+      logger.info('this info has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
+    })
 
     const exptectedMsg = 'this info has ****** and ****** and case-insensitive ******'
 
@@ -28,18 +40,9 @@ describe('Test Logger secret mask', () => {
   })
 
   test('masks secret values present in log.warn messages', () => {
-    let loggedMessage = null
-
-    // override the default console.log to capture the logged message
-    const defaultConsoleLog = console.log
-    console.log = (logPrefix, message) => {
-      loggedMessage = message
-      defaultConsoleLog(logPrefix, message)
-    }
-
-    logger.warn('this warning has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
-    // restore the default console.log before using "expect" to avoid weird log behaviors
-    console.log = defaultConsoleLog
+    const loggedMessage = captureConsoleLog(() => {
+      logger.warn('this warning has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
+    })
 
     const exptectedMsg = chalk.bold.yellow('this warning has ****** and ****** and case-insensitive ******')
 
@@ -48,18 +51,9 @@ describe('Test Logger secret mask', () => {
   })
 
   test('masks secret values present in log.error messages', () => {
-    let loggedMessage = null
-
-    // override the default console.log to capture the logged message
-    const defaultConsoleLog = console.log
-    console.log = (logPrefix, message) => {
-      loggedMessage = message
-      defaultConsoleLog(logPrefix, message)
-    }
-
-    logger.error(new Error('this error has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2'))
-    // restore the default console.log before using "expect" to avoid weird log behaviors
-    console.log = defaultConsoleLog
+    const loggedMessage = captureConsoleLog(() => {
+      logger.error(new Error('this error has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2'))
+    })
 
     const exptectedMsg = chalk.bold.red('Error: this error has ****** and ****** and case-insensitive ******')
 
@@ -68,19 +62,10 @@ describe('Test Logger secret mask', () => {
   })
 
   test('masks secret values present in log.error stack trace', () => {
-    let loggedMessage = null
-
-    // override the default console.log to capture the logged message
-    const defaultConsoleLog = console.log
-    console.log = (logPrefix, message) => {
-      loggedMessage = message
-      defaultConsoleLog(logPrefix, message)
-    }
-
-    const err = new Error('this error has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
-    logger.error(err, '', '', true)
-    // restore the default console.log before using "expect" to avoid weird log behaviors
-    console.log = defaultConsoleLog
+    const loggedMessage = captureConsoleLog(() => {
+      const err = new Error('this error has ToBeMasked1 and toBeMasked2 and case-insensitive TOBEMasKED2')
+      logger.error(err, '', '', true)
+    })
 
     const exptectedMsg = chalk.bold.red('Error: this error has ****** and ****** and case-insensitive ******')
 
@@ -92,22 +77,22 @@ describe('Test Logger secret mask', () => {
   })
 
   test('escape regex characters from secret values before masking them', () => {
-    let loggedMessage = null
-
-    // override the default console.log to capture the logged message
-    const defaultConsoleLog = console.log
-    console.log = (logPrefix, message) => {
-      loggedMessage = message
-      defaultConsoleLog(logPrefix, message)
-    }
-
-    logger.warn('this warning has ToBeMasked(And)?Escaped but not toBeMaskedEscaped ')
-    // restore the default console.log before using "expect" to avoid weird log behaviors
-    console.log = defaultConsoleLog
+    const loggedMessage = captureConsoleLog(() => {
+      logger.warn('this warning has ToBeMasked(And)?Escaped but not toBeMaskedEscaped ')
+    })
 
     const exptectedMsg = chalk.bold.yellow('this warning has ****** but not toBeMaskedEscaped ')
 
     expect(loggedMessage).toBeTruthy()
     expect(loggedMessage).toBe(exptectedMsg)
   })
+
+  test('masks inside object', () => {
+    const loggedMessage = captureConsoleLog(() => {
+      logger.warn({ a: 1, deep: { secret: 'there is a ToBeMasked1 hiding here' } })
+    })
+
+    expect(loggedMessage).toBeTruthy()
+    expect(!maskables.some((maskable) => loggedMessage.includes(maskable))).toBeTruthy()
+  })
 })