log template messages and errors (#4856)

* log.error accepting multiple arguments

* clean up

* warn, info, debug methods

* Update packages/dd-trace/src/log/writer.js

Co-authored-by: Attila Szegedi <szegedi@users.noreply.github.com>

* attila suggestion

* include error type in the telemetry log

* remove optional chaining to work in node 12

* remove optional chainingand ?? to work in node 12

---------

Co-authored-by: Attila Szegedi <szegedi@users.noreply.github.com>

packages/dd-trace/src/log/index.js

@@ -4,6 +4,7 @@ const coalesce = require('koalas')
 const { isTrue } = require('../util')
 const { debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels')
 const logWriter = require('./writer')
+const { Log } = require('./log')
 
 const memoize = func => {
   const cache = {}
@@ -18,10 +19,6 @@ const memoize = func => {
   return memoized
 }
 
-function processMsg (msg) {
-  return typeof msg === 'function' ? msg() : msg
-}
-
 const config = {
   enabled: false,
   logger: undefined,
@@ -52,37 +49,37 @@ const log = {
   reset () {
     logWriter.reset()
     this._deprecate = memoize((code, message) => {
-      errorChannel.publish(message)
+      errorChannel.publish(Log.parse(message))
       return true
     })
 
     return this
   },
 
-  debug (message) {
+  debug (...args) {
     if (debugChannel.hasSubscribers) {
-      debugChannel.publish(processMsg(message))
+      debugChannel.publish(Log.parse(...args))
     }
     return this
   },
 
-  info (message) {
+  info (...args) {
     if (infoChannel.hasSubscribers) {
-      infoChannel.publish(processMsg(message))
+      infoChannel.publish(Log.parse(...args))
     }
     return this
   },
 
-  warn (message) {
+  warn (...args) {
     if (warnChannel.hasSubscribers) {
-      warnChannel.publish(processMsg(message))
+      warnChannel.publish(Log.parse(...args))
     }
     return this
   },
 
-  error (err) {
+  error (...args) {
     if (errorChannel.hasSubscribers) {
-      errorChannel.publish(processMsg(err))
+      errorChannel.publish(Log.parse(...args))
     }
     return this
   },

packages/dd-trace/src/log/log.js

@@ -0,0 +1,52 @@
+'use strict'
+
+const { format } = require('util')
+
+class Log {
+  constructor (message, args, cause, delegate) {
+    this.message = message
+    this.args = args
+    this.cause = cause
+    this.delegate = delegate
+  }
+
+  get formatted () {
+    const { message, args } = this
+
+    let formatted = message
+    if (message && args && args.length) {
+      formatted = format(message, ...args)
+    }
+    return formatted
+  }
+
+  static parse (...args) {
+    let message, cause, delegate
+
+    const lastArg = args[args.length - 1]
+    if (lastArg && typeof lastArg === 'object' && lastArg.stack) { // lastArg instanceof Error?
+      cause = args.pop()
+    }
+
+    const firstArg = args.shift()
+    if (firstArg) {
+      if (typeof firstArg === 'string') {
+        message = firstArg
+      } else if (typeof firstArg === 'object') {
+        message = String(firstArg.message || firstArg)
+      } else if (typeof firstArg === 'function') {
+        delegate = firstArg
+      } else {
+        message = String(firstArg)
+      }
+    } else if (!cause) {
+      message = String(firstArg)
+    }
+
+    return new Log(message, args, cause, delegate)
+  }
+}
+
+module.exports = {
+  Log
+}

packages/dd-trace/src/log/writer.js

@@ -2,6 +2,7 @@
 
 const { storage } = require('../../../datadog-core')
 const { LogChannel } = require('./channels')
+const { Log } = require('./log')
 const defaultLogger = {
   debug: msg => console.debug(msg), /* eslint-disable-line no-console */
   info: msg => console.info(msg), /* eslint-disable-line no-console */
@@ -22,15 +23,15 @@ function withNoop (fn) {
 }
 
 function unsubscribeAll () {
-  logChannel.unsubscribe({ debug, info, warn, error })
+  logChannel.unsubscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError })
 }
 
 function toggleSubscription (enable, level) {
   unsubscribeAll()
 
   if (enable) {
     logChannel = new LogChannel(level)
-    logChannel.subscribe({ debug, info, warn, error })
+    logChannel.subscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError })
   }
 }
 
@@ -51,32 +52,62 @@ function reset () {
   toggleSubscription(false)
 }
 
-function error (err) {
-  if (typeof err !== 'object' || !err) {
-    err = String(err)
-  } else if (!err.stack) {
-    err = String(err.message || err)
+function getErrorLog (err) {
+  if (err && typeof err.delegate === 'function') {
+    const result = err.delegate()
+    return Array.isArray(result) ? Log.parse(...result) : Log.parse(result)
+  } else {
+    return err
   }
+}
 
-  if (typeof err === 'string') {
-    err = new Error(err)
-  }
+function onError (err) {
+  const { formatted, cause } = getErrorLog(err)
+
+  // calling twice logger.error() because Error cause is only available in nodejs v16.9.0
+  // TODO: replace it with Error(message, { cause }) when cause has broad support
+  if (formatted) withNoop(() => logger.error(new Error(formatted)))
+  if (cause) withNoop(() => logger.error(cause))
+}
+
+function onWarn (log) {
+  const { formatted, cause } = getErrorLog(log)
+  if (formatted) withNoop(() => logger.warn(formatted))
+  if (cause) withNoop(() => logger.warn(cause))
+}
 
-  withNoop(() => logger.error(err))
+function onInfo (log) {
+  const { formatted, cause } = getErrorLog(log)
+  if (formatted) withNoop(() => logger.info(formatted))
+  if (cause) withNoop(() => logger.info(cause))
 }
 
-function warn (message) {
-  if (!logger.warn) return debug(message)
-  withNoop(() => logger.warn(message))
+function onDebug (log) {
+  const { formatted, cause } = getErrorLog(log)
+  if (formatted) withNoop(() => logger.debug(formatted))
+  if (cause) withNoop(() => logger.debug(cause))
 }
 
-function info (message) {
-  if (!logger.info) return debug(message)
-  withNoop(() => logger.info(message))
+function error (...args) {
+  onError(Log.parse(...args))
+}
+
+function warn (...args) {
+  const log = Log.parse(...args)
+  if (!logger.warn) return onDebug(log)
+
+  onWarn(log)
+}
+
+function info (...args) {
+  const log = Log.parse(...args)
+  if (!logger.info) return onDebug(log)
+
+  onInfo(log)
 }
 
-function debug (message) {
-  withNoop(() => logger.debug(message))
+function debug (...args) {
+  onDebug(Log.parse(...args))
 }
 
 module.exports = { use, toggle, reset, error, warn, info, debug }

packages/dd-trace/src/telemetry/logs/index.js

@@ -35,18 +35,23 @@ function onLog (log) {
 }
 
 function onErrorLog (msg) {
-  if (msg instanceof Error) {
-    onLog({
-      level: 'ERROR',
-      message: msg.message,
-      stack_trace: msg.stack
-    })
-  } else if (typeof msg === 'string') {
-    onLog({
-      level: 'ERROR',
-      message: msg
-    })
+  const { message, cause } = msg
+  if (!message && !cause) return
+
+  const telLog = {
+    level: 'ERROR',
+
+    // existing log.error(err) without message will be reported as 'Generic Error'
+    message: message ?? 'Generic Error'
   }
+
+  if (cause) {
+    telLog.stack_trace = cause.stack
+    const errorType = cause.name ?? 'Error'
+    telLog.message = `${errorType}: ${telLog.message}`
+  }
+
+  onLog(telLog)
 }
 
 function start (config) {

packages/dd-trace/src/telemetry/logs/log-collector.js

@@ -48,16 +48,11 @@ function sanitize (logEntry) {
     .map(line => line.replace(ddBasePath, ''))
 
   logEntry.stack_trace = stackLines.join(EOL)
-  if (logEntry.stack_trace === '') {
-    // If entire stack was removed, we'd just have a message saying "omitted"
-    // in which case we'd rather not log it at all.
+  if (logEntry.stack_trace === '' && !logEntry.message) {
+    // If entire stack was removed and there is no message we'd rather not log it at all.
     return null
   }
 
-  if (!isDDCode) {
-    logEntry.message = 'omitted'
-  }
-
   return logEntry
 }
 
@@ -82,7 +77,7 @@ const logCollector = {
         return true
       }
     } catch (e) {
-      log.error(`Unable to add log to logCollector: ${e.message}`)
+      log.error('Unable to add log to logCollector: %s', e.message)
     }
     return false
   },

packages/dd-trace/test/log.spec.js

@@ -160,6 +160,7 @@ describe('log', () => {
         expect(console.error.firstCall.args[0]).to.have.property('message', 'error')
       })
 
+      // NOTE: There is no usage for this case. should we continue supporting it?
       it('should convert empty values to errors', () => {
         log.error()
 
@@ -191,6 +192,34 @@ describe('log', () => {
         expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
         expect(console.error.firstCall.args[0]).to.have.property('message', 'error')
       })
+
+      it('should allow a message + Error', () => {
+        log.error('this is an error', new Error('cause'))
+
+        expect(console.error).to.have.been.called
+        expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
+        expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error')
+        expect(console.error.secondCall.args[0]).to.be.instanceof(Error)
+        expect(console.error.secondCall.args[0]).to.have.property('message', 'cause')
+      })
+
+      it('should allow a templated message', () => {
+        log.error('this is an error of type: %s code: %i', 'ERR', 42)
+
+        expect(console.error).to.have.been.called
+        expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
+        expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42')
+      })
+
+      it('should allow a templated message + Error', () => {
+        log.error('this is an error of type: %s code: %i', 'ERR', 42, new Error('cause'))
+
+        expect(console.error).to.have.been.called
+        expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
+        expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42')
+        expect(console.error.secondCall.args[0]).to.be.instanceof(Error)
+        expect(console.error.secondCall.args[0]).to.have.property('message', 'cause')
+      })
     })
 
     describe('toggle', () => {

packages/dd-trace/test/telemetry/logs/index.spec.js

@@ -4,6 +4,7 @@ require('../../setup/tap')
 
 const { match } = require('sinon')
 const proxyquire = require('proxyquire')
+const { Log } = require('../../../src/log/log')
 
 describe('telemetry logs', () => {
   let defaultConfig
@@ -141,13 +142,14 @@ describe('telemetry logs', () => {
       it('should be called when an Error object is published to datadog:log:error', () => {
         const error = new Error('message')
         const stack = error.stack
-        errorLog.publish(error)
+        errorLog.publish({ cause: error })
 
-        expect(logCollectorAdd).to.be.calledOnceWith(match({ message: 'message', level: 'ERROR', stack_trace: stack }))
+        expect(logCollectorAdd)
+          .to.be.calledOnceWith(match({ message: `${error.name}: Generic Error`, level: 'ERROR', stack_trace: stack }))
       })
 
       it('should be called when an error string is published to datadog:log:error', () => {
-        errorLog.publish('custom error message')
+        errorLog.publish({ message: 'custom error message' })
 
         expect(logCollectorAdd).to.be.calledOnceWith(match({
           message: 'custom error message',
@@ -161,6 +163,12 @@ describe('telemetry logs', () => {
 
         expect(logCollectorAdd).not.to.be.called
       })
+
+      it('should not be called when an object without message and stack is published to datadog:log:error', () => {
+        errorLog.publish(Log.parse(() => new Error('error')))
+
+        expect(logCollectorAdd).not.to.be.called
+      })
     })
   })
 

packages/dd-trace/test/telemetry/logs/log-collector.spec.js

@@ -63,7 +63,7 @@ describe('telemetry log collector', () => {
       })).to.be.true
     })
 
-    it('should not include original message if first frame is not a dd frame', () => {
+    it('should include original message if first frame is not a dd frame', () => {
       const thirdPartyFrame = `at callFn (/this/is/not/a/dd/frame/runnable.js:366:21)
         at T (${ddBasePath}packages/dd-trace/test/telemetry/logs/log_collector.spec.js:29:21)`
       const stack = new Error('Error 1')
@@ -77,7 +77,7 @@ describe('telemetry log collector', () => {
 
       expect(logCollector.add({ message: 'Error 1', level: 'ERROR', stack_trace: stack })).to.be.true
       expect(logCollector.hasEntry({
-        message: 'omitted',
+        message: 'Error 1',
         level: 'ERROR',
         stack_trace: ddFrames
       })).to.be.true