Inject trace ids into paperplane logs

packages/datadog-plugin-paperplane/src/index.js

@@ -12,6 +12,25 @@ const traceRoute = handler => req => {
   return handler(req)
 }
 
+const wrapLogger = tracer => logger => record => {
+  const span = tracer.scope().active()
+
+  if (!span) return logger(record)
+
+  const correlation = {
+    dd: {
+      trace_id: span.context().toTraceId(),
+      span_id: span.context().toSpanId()
+    }
+  }
+
+  record = record instanceof Error
+    ? Object.assign(record, correlation)
+    : Object.assign({}, record, correlation)
+
+  return logger(record)
+}
+
 const wrapMount = (tracer, config) => mount => opts => {
   const handler = mount(opts)
 
@@ -34,19 +53,53 @@ const wrapRoutes = tracer => routes => handlers => {
   return routes(traced)
 }
 
-function patch (paperplane, tracer, config) {
-  config = web.normalizeConfig(config)
-  this.wrap(paperplane, 'mount', wrapMount(tracer, config))
-  this.wrap(paperplane, 'routes', wrapRoutes(tracer))
-}
-
-function unpatch (paperplane) {
-  this.unwrap(paperplane, ['mount', 'routes'])
-}
-
-module.exports = {
-  name: 'paperplane',
-  versions: ['>=2.3'],
-  patch,
-  unpatch
-}
+module.exports = [
+  {
+    name: 'paperplane',
+    versions: ['>=2.3.2'],
+    file: 'lib/logger.js',
+    patch (exports, tracer) {
+      if (tracer._logInjection) {
+        this.wrap(exports, 'logger', wrapLogger(tracer))
+      }
+    },
+    unpatch (exports) {
+      this.unwrap(exports, 'logger')
+    }
+  },
+  {
+    name: 'paperplane',
+    versions: ['>=2.3.2'],
+    file: 'lib/mount.js',
+    patch (exports, tracer, config) {
+      config = web.normalizeConfig(config)
+      this.wrap(exports, 'mount', wrapMount(tracer, config))
+    },
+    unpatch (exports) {
+      this.unwrap(exports, 'mount')
+    }
+  },
+  {
+    name: 'paperplane',
+    versions: ['>=2.3.2'],
+    file: 'lib/routes.js',
+    patch (exports, tracer) {
+      this.wrap(exports, 'routes', wrapRoutes(tracer))
+    },
+    unpatch (exports) {
+      this.unwrap(exports, 'routes')
+    }
+  },
+  {
+    name: 'paperplane',
+    versions: ['2.3.0 - 2.3.1'],
+    patch (paperplane, tracer, config) {
+      config = web.normalizeConfig(config)
+      this.wrap(paperplane, 'mount', wrapMount(tracer, config))
+      this.wrap(paperplane, 'routes', wrapRoutes(tracer))
+    },
+    unpatch (paperplane) {
+      this.unwrap(paperplane, ['mount', 'routes'])
+    }
+  }
+]

packages/datadog-plugin-paperplane/test/index.spec.js

@@ -3,6 +3,7 @@
 const axios = require('axios')
 const getPort = require('get-port')
 const http = require('http')
+const semver = require('semver')
 
 const agent = require('../../dd-trace/test/plugins/agent')
 const plugin = require('../src')
@@ -26,8 +27,23 @@ const then = (x, f) =>
 describe('Plugin', () => {
   let paperplane
   let server
+  let span
   let tracer
 
+  const sandbox = sinon.createSandbox()
+
+  before(() => {
+    sandbox.spy(console, 'info')
+  })
+
+  afterEach(() => {
+    sandbox.resetHistory()
+  })
+
+  after(() => {
+    sandbox.restore()
+  })
+
   describe('paperplane', () => {
     withVersions(plugin, 'paperplane', version => {
       beforeEach(() => {
@@ -412,6 +428,26 @@ describe('Plugin', () => {
             })
           })
         })
+
+        if (semver.intersects(version, '>=2.3.1')) {
+          it('should not alter the behavior of `logger`', done => {
+            span = tracer.startSpan('test')
+
+            tracer.scope().activate(span, () => {
+              /* eslint-disable no-console */
+              paperplane.logger({ message: ':datadoge:' })
+
+              expect(console.info).to.have.been.called
+
+              const record = JSON.parse(console.info.firstCall.args[0])
+
+              expect(record).to.not.have.property('dd')
+              expect(record).to.have.property('message', ':datadoge:')
+              done()
+              /* eslint-enable no-console */
+            })
+          })
+        }
       })
 
       describe('with configuration', () => {
@@ -428,6 +464,7 @@ describe('Plugin', () => {
         })
 
         beforeEach(() => {
+          tracer._tracer._logInjection = true
           paperplane = require(`../../../versions/paperplane@${version}`).get()
         })
 
@@ -521,6 +558,68 @@ describe('Plugin', () => {
             })
           })
         })
+
+        if (semver.intersects(version, '>=2.3.2')) {
+          it('should add the trace ids to logs', done => {
+            span = tracer.startSpan('test')
+
+            tracer.scope().activate(span, () => {
+              /* eslint-disable no-console */
+              paperplane.logger({ message: ':datadoge:' })
+
+              expect(console.info).to.have.been.called
+
+              const record = JSON.parse(console.info.firstCall.args[0])
+
+              expect(record).to.have.deep.property('dd', {
+                trace_id: span.context().toTraceId(),
+                span_id: span.context().toSpanId()
+              })
+
+              expect(record).to.have.property('message', ':datadoge:')
+              done()
+              /* eslint-enable no-console */
+            })
+          })
+
+          it('should add the trace ids to error logs', done => {
+            span = tracer.startSpan('test')
+
+            tracer.scope().activate(span, () => {
+              /* eslint-disable no-console */
+              const err = new Error('Bad things happened')
+              paperplane.logger(err)
+
+              expect(console.info).to.have.been.called
+
+              const record = JSON.parse(console.info.firstCall.args[0])
+
+              expect(record).to.have.deep.property('dd', {
+                trace_id: span.context().toTraceId(),
+                span_id: span.context().toSpanId()
+              })
+
+              expect(record).to.have.property('message', 'Bad things happened')
+              expect(record).to.have.property('name', 'Error')
+              expect(record).to.have.property('stack')
+              done()
+              /* eslint-enable no-console */
+            })
+          })
+
+          it('should not alter logs with no active span', () => {
+            /* eslint-disable no-console */
+            paperplane.logger({ message: ':datadoge:' })
+
+            expect(console.info).to.have.been.called
+
+            const record = JSON.parse(console.info.firstCall.args[0])
+
+            expect(record).to.not.have.property('dd')
+            expect(record).to.have.property('message', ':datadoge:')
+            /* eslint-enable no-console */
+          })
+        }
       })
     })
   })