companion: add traceID to follow logs through

package.json

@@ -41,6 +41,7 @@
     "express": "4.17.1",
     "express-interceptor": "1.2.0",
     "express-prom-bundle": "3.3.0",
+    "express-request-id": "1.4.1",
     "express-session": "1.15.6",
     "grant-express": "4.1.2",
     "helmet": "3.8.2",

src/server/Uploader.js

@@ -57,7 +57,7 @@ class Uploader {
     //     .on('error', (err) => logger.error(`${this.shortToken} ${err}`, 'uploader.duplex.error'))
     // }
     this.writeStream = fs.createWriteStream(this.path, { mode: 0o666 }) // no executable files
-      .on('error', (err) => logger.error(`${this.shortToken} ${err}`, 'uploader.write.error'))
+      .on('error', (err) => logger.error(`${err}`, 'uploader.write.error', this.shortToken))
     /** @type {number} */
     this.emittedProgress = 0
     this.storage = options.storage
@@ -80,6 +80,17 @@ class Uploader {
     }
   }
 
+  /**
+   * returns a substring of the token. Used as traceId for logging
+   * we avoid using the entire token because this is meant to be a short term
+   * access token between uppy client and companion websocket
+   * @param {string} token the token to Shorten
+   * @returns {string}
+   */
+  static shortenToken (token) {
+    return token.substring(0, 8)
+  }
+
   /**
    * the number of bytes written into the streams
    */
@@ -128,10 +139,12 @@ class Uploader {
   }
 
   /**
-   * returns a substring of the token
+   * returns a substring of the token. Used as traceId for logging
+   * we avoid using the entire token because this is meant to be a short term
+   * access token between uppy client and companion websocket
    */
   get shortToken () {
-    return this.token.substring(0, 8)
+    return Uploader.shortenToken(this.token)
   }
 
   /**
@@ -140,7 +153,7 @@ class Uploader {
    */
   onSocketReady (callback) {
     emitter().once(`connection:${this.token}`, () => callback())
-    logger.debug(`${this.shortToken} waiting for connection`, 'uploader.socket.wait')
+    logger.debug(`waiting for connection`, 'uploader.socket.wait', this.shortToken)
   }
 
   cleanUp () {
@@ -178,7 +191,7 @@ class Uploader {
     }
 
     this.writeStream.write(chunk, () => {
-      logger.debug(`${this.shortToken} ${this.bytesWritten} bytes`, 'uploader.download.progress')
+      logger.debug(`${this.bytesWritten} bytes`, 'uploader.download.progress', this.shortToken)
       if (protocol === PROTOCOLS.multipart || protocol === PROTOCOLS.tus) {
         return this.emitIllusiveProgress()
       }
@@ -259,8 +272,9 @@ class Uploader {
     const illusiveBytesUploaded = (this.bytesWritten / 2) + (bytesUploaded / 2)
 
     logger.debug(
-      `${this.shortToken} ${bytesUploaded} ${illusiveBytesUploaded} ${bytesTotal}`,
-      'uploader.illusive.progress'
+      `${bytesUploaded} ${illusiveBytesUploaded} ${bytesTotal}`,
+      'uploader.illusive.progress',
+      this.shortToken
     )
     this.emitProgress(illusiveBytesUploaded, bytesTotal)
   }
@@ -278,8 +292,9 @@ class Uploader {
     const percentage = (bytesUploaded / bytesTotal * 100)
     const formatPercentage = percentage.toFixed(2)
     logger.debug(
-      `${this.shortToken} ${bytesUploaded} ${bytesTotal} ${formatPercentage}%`,
-      'uploader.upload.progress'
+      `${bytesUploaded} ${bytesTotal} ${formatPercentage}%`,
+      'uploader.upload.progress',
+      this.shortToken
     )
 
     const dataToEmit = {

src/server/controllers/callback.js

@@ -18,7 +18,7 @@ module.exports = function callback (req, res, next) {
   }
 
   req.uppy.providerTokens[providerName] = req.session.grant.response.access_token
-  logger.debug(`Generating auth token for provider ${providerName}.`)
+  logger.debug(`Generating auth token for provider ${providerName}.`, null, req.id)
   const uppyAuthToken = tokenService.generateToken(req.uppy.providerTokens, req.uppy.options.secret)
   return res.redirect(req.uppy.buildURL(`/${providerName}/send-token?uppyAuthToken=${uppyAuthToken}`, true))
 }

src/server/controllers/get.js

@@ -17,11 +17,11 @@ function get (req, res, next) {
     }
 
     if (!size) {
-      logger.error('unable to determine file size', 'controller.get.provider.size')
+      logger.error('unable to determine file size', 'controller.get.provider.size', req.id)
       return res.status(400).json({ error: 'unable to determine file size' })
     }
 
-    logger.debug('Instantiating uploader.')
+    logger.debug('Instantiating uploader.', null, req.id)
     const uploader = new Uploader({
       uppyOptions: req.uppy.options,
       endpoint: body.endpoint,
@@ -47,10 +47,10 @@ function get (req, res, next) {
 
     // wait till the client has connected to the socket, before starting
     // the download, so that the client can receive all download/upload progress.
-    logger.debug('Waiting for socket connection before beginning remote download.')
+    logger.debug('Waiting for socket connection before beginning remote download.', null, req.id)
     // waiting for socketReady.
     uploader.onSocketReady(() => {
-      logger.debug('Socket connection received. Starting remote download.')
+      logger.debug('Socket connection received. Starting remote download.', null, req.id)
       provider.download({ id, token, query: req.query }, uploader.handleChunk.bind(uploader))
     })
     const response = uploader.getResponse()

src/server/controllers/url.js

@@ -19,17 +19,17 @@ module.exports = () => {
  * @param {object} res expressJS response object
  */
 const meta = (req, res) => {
-  logger.debug('URL file import handler running')
+  logger.debug('URL file import handler running', null, req.id)
 
   if (!validator.isURL(req.body.url, { require_protocol: true, require_tld: !req.uppy.options.debug })) {
-    logger.debug('Invalid request body detected. Exiting url meta handler.')
+    logger.debug('Invalid request body detected. Exiting url meta handler.', null, req.id)
     return res.status(400).json({ error: 'Invalid request body' })
   }
 
   utils.getURLMeta(req.body.url)
     .then((meta) => res.json(meta))
     .catch((err) => {
-      logger.error(err, 'controller.url.meta.error')
+      logger.error(err, 'controller.url.meta.error', req.id)
       return res.status(500).json({ error: err })
     })
 }
@@ -42,13 +42,13 @@ const meta = (req, res) => {
  * @param {object} res expressJS response object
  */
 const get = (req, res) => {
-  logger.debug('URL file import handler running')
+  logger.debug('URL file import handler running', null, req.id)
 
   utils.getURLMeta(req.body.url)
     .then(({ size }) => {
       // @ts-ignore
       const { filePath } = req.uppy.options
-      logger.debug('Instantiating uploader.')
+      logger.debug('Instantiating uploader.', null, req.id)
       const uploader = new Uploader({
         uppyOptions: req.uppy.options,
         endpoint: req.body.endpoint,
@@ -68,16 +68,16 @@ const get = (req, res) => {
         return
       }
 
-      logger.debug('Waiting for socket connection before beginning remote download.')
+      logger.debug('Waiting for socket connection before beginning remote download.', null, req.id)
       uploader.onSocketReady(() => {
-        logger.debug('Socket connection received. Starting remote download.')
-        downloadURL(req.body.url, uploader.handleChunk.bind(uploader))
+        logger.debug('Socket connection received. Starting remote download.', null, req.id)
+        downloadURL(req.body.url, uploader.handleChunk.bind(uploader), req.id)
       })
 
       const response = uploader.getResponse()
       res.status(response.status).json(response.body)
     }).catch((err) => {
-      logger.error(err, 'controller.url.get.error')
+      logger.error(err, 'controller.url.get.error', req.id)
       res.json({ err })
     })
 }
@@ -88,8 +88,9 @@ const get = (req, res) => {
  *
  * @param {string} url
  * @param {typeof Function} onDataChunk
+ * @param {string=} traceId
  */
-const downloadURL = (url, onDataChunk) => {
+const downloadURL = (url, onDataChunk, traceId) => {
   const opts = {
     uri: url,
     method: 'GET',
@@ -99,5 +100,5 @@ const downloadURL = (url, onDataChunk) => {
   request(opts)
     .on('data', onDataChunk)
     .on('end', () => onDataChunk(null))
-    .on('error', (err) => logger.error(err, 'controller.url.download.error'))
+    .on('error', (err) => logger.error(err, 'controller.url.download.error', traceId))
 }

src/server/logger.js

@@ -4,39 +4,43 @@ const chalk = require('chalk')
  * INFO level log
  * @param {string} 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
  */
-exports.info = (msg, tag) => {
-  log(msg, tag, 'info')
+exports.info = (msg, tag, traceId) => {
+  log(msg, tag, 'info', traceId)
 }
 
 /**
  * WARN level log
  * @param {string} 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
  */
-exports.warn = (msg, tag) => {
+exports.warn = (msg, tag, traceId) => {
   // @ts-ignore
-  log(msg, tag, 'warn', chalk.bold.yellow)
+  log(msg, tag, 'warn', traceId, chalk.bold.yellow)
 }
 
 /**
  * ERROR level log
  * @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
  */
-exports.error = (msg, tag) => {
+exports.error = (msg, tag, traceId) => {
   // @ts-ignore
-  log(msg, tag, 'error', chalk.bold.red)
+  log(msg, tag, 'error', traceId, chalk.bold.red)
 }
 
 /**
  * DEBUG level log
  * @param {string} 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
  */
-exports.debug = (msg, tag) => {
+exports.debug = (msg, tag, traceId) => {
   if (process.env.NODE_ENV !== 'production') {
-    log(msg, tag, 'debug')
+    log(msg, tag, 'debug', traceId)
   }
 }
 
@@ -46,11 +50,15 @@ exports.debug = (msg, tag) => {
  * @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
  */
-const log = (msg, tag, level, color) => {
+const log = (msg, tag, level, id, color) => {
   const time = new Date().toISOString()
+  tag = tag || ''
+  id = id || ''
+  const whitespace = tag && id ? ' ' : ''
   color = color || ((message) => message)
   // exclude msg from template string so values such as error objects
   // can be well formatted
-  console.log(color(`companion: ${time} [${level}] ${tag || ''}`), color(msg))
+  console.log(color(`companion: ${time} [${level}] ${id}${whitespace}${tag}`), color(msg))
 }

src/server/middlewares.js

@@ -3,12 +3,12 @@ const logger = require('./logger')
 
 exports.hasSessionAndProvider = (req, res, next) => {
   if (!req.session || !req.body) {
-    logger.debug('No session/body attached to req object. Exiting dispatcher.')
+    logger.debug('No session/body attached to req object. Exiting dispatcher.', null, req.id)
     return res.sendStatus(400)
   }
 
   if (!req.uppy.provider) {
-    logger.debug('No provider/provider-handler found. Exiting dispatcher.')
+    logger.debug('No provider/provider-handler found. Exiting dispatcher.', null, req.id)
     return res.sendStatus(400)
   }
 

src/server/provider/index.js

@@ -78,7 +78,7 @@ module.exports.getProviderMiddleware = (providers) => {
     if (providers[providerName] && validOptions(req.uppy.options)) {
       req.uppy.provider = new providers[providerName]({ providerName, config })
     } else {
-      logger.warn('invalid provider options detected. Provider will not be loaded', 'provider.middleware.invalid')
+      logger.warn('invalid provider options detected. Provider will not be loaded', 'provider.middleware.invalid', req.id)
     }
     next()
   }

src/standalone/index.js

@@ -7,6 +7,7 @@ const bodyParser = require('body-parser')
 // @ts-ignore
 const promBundle = require('express-prom-bundle')
 const session = require('express-session')
+const addRequestId = require('express-request-id')()
 const helper = require('./helper')
 // @ts-ignore
 const { version } = require('../../package.json')
@@ -29,6 +30,7 @@ if (app.get('env') !== 'test') {
   clearInterval(promInterval)
 }
 
+app.use(addRequestId)
 // log server requests.
 app.use(morgan('combined'))
 morgan.token('url', (req, res) => {

src/uppy.js

@@ -17,6 +17,7 @@ const interceptor = require('express-interceptor')
 const logger = require('./server/logger')
 const { STORAGE_PREFIX } = require('./server/Uploader')
 const middlewares = require('./server/middlewares')
+const { shortenToken } = require('./server/Uploader')
 
 const providers = providerManager.getDefaultProviders()
 const defaultOptions = {
@@ -141,15 +142,15 @@ module.exports.socket = (server) => {
      */
     function sendProgress (data) {
       ws.send(jsonStringify(data), (err) => {
-        if (err) logger.error(err, 'socket.progress.error')
+        if (err) logger.error(err, 'socket.progress.error', shortenToken(token))
       })
     }
 
     // if the redisClient is available, then we attempt to check the storage
     // if we have any already stored progress data on the upload.
     if (redisClient) {
       redisClient.get(`${STORAGE_PREFIX}:${token}`, (err, data) => {
-        if (err) logger.error(err, 'socket.redis.error')
+        if (err) logger.error(err, 'socket.redis.error', shortenToken(token))
         if (data) {
           const dataObj = JSON.parse(data.toString())
           if (dataObj.action) sendProgress(dataObj)
@@ -185,11 +186,13 @@ const interceptGrantErrorResponse = interceptor((req, res) => {
     intercept: (body, send) => {
       const unwantedBody = 'error=Grant%3A%20missing%20session%20or%20misconfigured%20provider'
       if (body === unwantedBody) {
-        logger.error(`grant.js responded with error: ${body}`, 'grant.oauth.error')
+        logger.error(`grant.js responded with error: ${body}`, 'grant.oauth.error', req.id)
         res.set('Content-Type', 'text/plain')
+        const reqHint = req.id ? `Request ID: ${req.id}` : ''
         send([
           'Companion was unable to complete the OAuth process :(',
-          'Error: User session is missing or the Provider was misconfigured'
+          'Error: User session is missing or the Provider was misconfigured',
+          reqHint
         ].join('\n'))
       } else {
         send(body)