companion: mask secrets present in log messages (#2214)

* companion: mask secrets present in log messages

* companion: escape secrets that should be masked

* companion: log error stacks optionally

* companion: restore old node enging compatibility

* companion: refactor conditional error response

packages/@uppy/companion/package.json

@@ -37,6 +37,7 @@
     "common-tags": "1.8.0",
     "connect-redis": "4.0.3",
     "cookie-parser": "1.4.4",
+    "escape-string-regexp": "4.0.0",
     "express": "4.17.1",
     "express-interceptor": "1.2.0",
     "express-prom-bundle": "3.3.0",

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

@@ -57,6 +57,9 @@ module.exports.app = (options = {}) => {
     providerManager.addCustomProviders(customProviders, providers, grantConfig)
   }
 
+  // mask provider secrets from log messages
+  maskLogger(options)
+
   // create singleton redis client
   if (options.redisUrl) {
     redis.client(merge({ url: options.redisUrl }, options.redisOptions || {}))
@@ -272,3 +275,28 @@ const getOptionsMiddleware = (options) => {
 
   return middleware
 }
+
+/**
+ * Informs the logger about all provider secrets that should be masked
+ * if they are found in a log message
+ * @param {object} companionOptions
+ */
+const maskLogger = (companionOptions) => {
+  const secrets = []
+  const { providerOptions, customProviders } = companionOptions
+  Object.keys(providerOptions).forEach((provider) => {
+    if (providerOptions[provider].secret) {
+      secrets.push(providerOptions[provider].secret)
+    }
+  })
+
+  if (customProviders) {
+    Object.keys(customProviders).forEach((provider) => {
+      if (customProviders[provider].config && customProviders[provider].config.secret) {
+        secrets.push(customProviders[provider].config.secret)
+      }
+    })
+  }
+
+  logger.setMaskables(secrets)
+}

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

@@ -1,4 +1,19 @@
 const chalk = require('chalk')
+const escapeStringRegexp = require('escape-string-regexp')
+
+const valuesToMask = []
+/**
+ * Adds a list of strings that should be masked by the logger.
+ * This function can only be called once through out the life of the server.
+ * @param {Array} maskables a list of strings to be masked
+ */
+exports.setMaskables = (maskables) => {
+  maskables.forEach((i) => {
+    valuesToMask.push(escapeStringRegexp(i))
+  })
+
+  Object.freeze(valuesToMask)
+}
 
 /**
  * INFO level log
@@ -26,10 +41,11 @@ exports.warn = (msg, tag, traceId) => {
  * @param {string | Error} msg the message to log
  * @param {string=} tag a unique tag to easily search for this message
  * @param {string=} traceId 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
  */
-exports.error = (msg, tag, traceId) => {
+exports.error = (msg, tag, traceId, shouldLogStackTrace) => {
   // @ts-ignore
-  log(msg, tag, 'error', traceId, chalk.bold.red)
+  log(msg, tag, 'error', traceId, chalk.bold.red, shouldLogStackTrace)
 }
 
 /**
@@ -51,14 +67,42 @@ exports.debug = (msg, tag, traceId) => {
  * @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) => {
+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/src/standalone/index.js

@@ -5,6 +5,7 @@ const helmet = require('helmet')
 const morgan = require('morgan')
 const bodyParser = require('body-parser')
 const redis = require('../server/redis')
+const logger = require('../server/logger')
 const { parseURL } = require('../server/helpers/utils')
 const merge = require('lodash.merge')
 // @ts-ignore
@@ -194,24 +195,22 @@ app.use((req, res, next) => {
   return res.status(404).json({ message: 'Not Found' })
 })
 
-if (app.get('env') === 'production') {
-  // @ts-ignore
-  app.use((err, req, res, next) => {
+// @ts-ignore
+app.use((err, req, res, next) => {
+  const logStackTrace = true
+  if (app.get('env') === 'production') {
     // if the error is a URIError from the requested URL we only log the error message
     // to avoid uneccessary error alerts
     if (err.status === 400 && err instanceof URIError) {
-      console.error('\x1b[31m', req.id, err.message, '\x1b[0m')
+      logger.error(err.message, 'root.error', req.id)
     } else {
-      console.error('\x1b[31m', req.id, err, '\x1b[0m')
+      logger.error(err, 'root.error', req.id, logStackTrace)
     }
     res.status(err.status || 500).json({ message: 'Something went wrong', requestId: req.id })
-  })
-} else {
-  // @ts-ignore
-  app.use((err, req, res, next) => {
-    console.error('\x1b[31m', req.id, err, '\x1b[0m')
+  } else {
+    logger.error(err, 'root.error', req.id, logStackTrace)
     res.status(err.status || 500).json({ message: err.message, error: err, requestId: req.id })
-  })
-}
+  }
+})
 
 module.exports = { app, companionOptions }

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

@@ -0,0 +1,113 @@
+/* global test:false, expect:false, describe:false, beforeAll:false, */
+const logger = require('../../src/server/logger')
+const chalk = require('chalk')
+
+describe('Test Logger secret mask', () => {
+  beforeAll(() => {
+    logger.setMaskables(['ToBeMasked1', 'toBeMasked2', 'toBeMasked(And)?Escaped'])
+  })
+
+  test('masks secret values present in log.info 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.info('this info 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 exptectedMsg = 'this info has ****** and ****** and case-insensitive ******'
+
+    expect(loggedMessage).toBeTruthy()
+    expect(loggedMessage).toBe(exptectedMsg)
+  })
+
+  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 exptectedMsg = chalk.bold.yellow('this warning has ****** and ****** and case-insensitive ******')
+
+    expect(loggedMessage).toBeTruthy()
+    expect(loggedMessage).toBe(exptectedMsg)
+  })
+
+  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 exptectedMsg = chalk.bold.red('Error: this error has ****** and ****** and case-insensitive ******')
+
+    expect(loggedMessage).toBeTruthy()
+    expect(loggedMessage).toBe(exptectedMsg)
+  })
+
+  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 exptectedMsg = chalk.bold.red('Error: this error has ****** and ****** and case-insensitive ******')
+
+    expect(loggedMessage).toBeTruthy()
+    expect(loggedMessage.startsWith(exptectedMsg)).toBe(true)
+    expect(loggedMessage.includes('ToBeMasked1')).toBe(false)
+    expect(loggedMessage.includes('toBeMasked2')).toBe(false)
+    expect(loggedMessage.includes('TOBEMasKED2')).toBe(false)
+  })
+
+  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 exptectedMsg = chalk.bold.yellow('this warning has ****** but not toBeMaskedEscaped ')
+
+    expect(loggedMessage).toBeTruthy()
+    expect(loggedMessage).toBe(exptectedMsg)
+  })
+})