fix invalid output for log.trace (#5047)

* fix invalid output for log.trace

* move string formatting to logger and improve output

* change depth

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

@@ -1,6 +1,7 @@
 'use strict'
 
 const coalesce = require('koalas')
+const { inspect } = require('util')
 const { isTrue } = require('../util')
 const { traceChannel, debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels')
 const logWriter = require('./writer')
@@ -59,9 +60,18 @@ const log = {
   trace (...args) {
     if (traceChannel.hasSubscribers) {
       const logRecord = {}
+
       Error.captureStackTrace(logRecord, this.trace)
-      const stack = logRecord.stack.split('\n')[1].replace(/^\s+at ([^\s]) .+/, '$1')
-      traceChannel.publish(Log.parse('Trace', args, { stack }))
+
+      const fn = logRecord.stack.split('\n')[1].replace(/^\s+at ([^\s]+) .+/, '$1')
+      const params = args.map(a => {
+        return a && a.hasOwnProperty('toString') && typeof a.toString === 'function'
+          ? a.toString()
+          : inspect(a, { depth: 3, breakLength: Infinity, compact: true })
+      }).join(', ')
+      const formatted = logRecord.stack.replace('Error: ', `Trace: ${fn}(${params})`)
+
+      traceChannel.publish(Log.parse(formatted))
     }
     return this
   },

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

@@ -4,7 +4,6 @@ const { storage } = require('../../../datadog-core')
 const { LogChannel } = require('./channels')
 const { Log } = require('./log')
 const defaultLogger = {
-  trace: msg => console.trace(msg), /* eslint-disable-line no-console */
   debug: msg => console.debug(msg), /* eslint-disable-line no-console */
   info: msg => console.info(msg), /* eslint-disable-line no-console */
   warn: msg => console.warn(msg), /* eslint-disable-line no-console */
@@ -91,8 +90,10 @@ function onDebug (log) {
 
 function onTrace (log) {
   const { formatted, cause } = getErrorLog(log)
-  if (formatted) withNoop(() => logger.trace(formatted))
-  if (cause) withNoop(() => logger.trace(cause))
+  // Using logger.debug() because not all loggers have trace level,
+  // and console.trace() has a completely different meaning.
+  if (formatted) withNoop(() => logger.debug(formatted))
+  if (cause) withNoop(() => logger.debug(cause))
 }
 
 function error (...args) {

packages/dd-trace/src/opentracing/span.js

@@ -107,7 +107,7 @@ class DatadogSpan {
 
   toString () {
     const spanContext = this.context()
-    const resourceName = spanContext._tags['resource.name']
+    const resourceName = spanContext._tags['resource.name'] || ''
     const resource = resourceName.length > 100
       ? `${resourceName.substring(0, 97)}...`
       : resourceName

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

@@ -86,7 +86,6 @@ describe('log', () => {
       sinon.stub(console, 'error')
       sinon.stub(console, 'warn')
       sinon.stub(console, 'debug')
-      sinon.stub(console, 'trace')
 
       error = new Error()
 
@@ -105,7 +104,6 @@ describe('log', () => {
       console.error.restore()
       console.warn.restore()
       console.debug.restore()
-      console.trace.restore()
     })
 
     it('should support chaining', () => {
@@ -145,14 +143,20 @@ describe('log', () => {
       it('should not log to console by default', () => {
         log.trace('trace')
 
-        expect(console.trace).to.not.have.been.called
+        expect(console.debug).to.not.have.been.called
       })
 
-      it('should log to console after setting log level to trace', () => {
+      it('should log to console after setting log level to trace', function foo () {
         log.toggle(true, 'trace')
-        log.trace('argument')
-
-        expect(console.trace).to.have.been.calledTwice
+        log.trace('argument', { hello: 'world' }, {
+          toString: () => 'string'
+        }, { foo: 'bar' })
+
+        expect(console.debug).to.have.been.calledOnce
+        expect(console.debug.firstCall.args[0]).to.match(
+          /^Trace: Test.foo\('argument', { hello: 'world' }, string, { foo: 'bar' }\)/
+        )
+        expect(console.debug.firstCall.args[0].split('\n').length).to.be.gte(3)
       })
     })