add automatic log correlation of tracer identifiers for pino

.circleci/config.yml

@@ -158,6 +158,14 @@ jobs:
           - SERVICES=
           - PLUGINS=bluebird
 
+  node-bunyan:
+    <<: *node-plugin-base
+    docker:
+      - image: node:8
+        environment:
+          - SERVICES=
+          - PLUGINS=bunyan
+
   node-elasticsearch:
     <<: *node-plugin-base
     docker:
@@ -243,6 +251,14 @@ jobs:
           - MONGODB_REPLICA_SET_MODE=primary
           - MONGODB_ADVERTISED_HOSTNAME=localhost
 
+  node-pino:
+    <<: *node-plugin-base
+    docker:
+      - image: node:8
+        environment:
+          - SERVICES=
+          - PLUGINS=pino
+
   node-postgres:
     <<: *node-plugin-base
     docker:
@@ -293,6 +309,14 @@ jobs:
           - SERVICES=
           - PLUGINS=when
 
+  node-winston:
+    <<: *node-plugin-base
+    docker:
+      - image: node:8
+        environment:
+          - SERVICES=
+          - PLUGINS=winston
+
 workflows:
   version: 2
   build:
@@ -307,6 +331,7 @@ workflows:
       - node-amqplib
       - node-amqp10
       - node-bluebird
+      - node-bunyan
       - node-elasticsearch
       - node-express
       - node-graphql
@@ -316,11 +341,13 @@ workflows:
       - node-memcached
       - node-mongodb-core
       - node-mysql
+      - node-pino
       - node-postgres
       - node-q
       - node-redis
       - node-restify
       - node-when
+      - node-winston
   nightly:
     triggers:
       - schedule:
@@ -338,6 +365,7 @@ workflows:
       - node-amqplib
       - node-amqp10
       - node-bluebird
+      - node-bunyan
       - node-elasticsearch
       - node-express
       - node-graphql
@@ -347,8 +375,10 @@ workflows:
       - node-memcached
       - node-mongodb-core
       - node-mysql
+      - node-pino
       - node-postgres
       - node-q
       - node-redis
       - node-restify
       - node-when
+      - node-winston

src/instrumenter.js

@@ -120,7 +120,7 @@ class Instrumenter {
       .filter(plugin => [].concat(plugin).some(instrumentation =>
         filename(instrumentation) === moduleName && matchVersion(moduleVersion, instrumentation.versions)
       ))
-      .forEach(plugin => this._validate(plugin, moduleBaseDir))
+      .forEach(plugin => this._validate(plugin, moduleBaseDir, moduleVersion))
 
     this._plugins
       .forEach((meta, plugin) => {
@@ -150,11 +150,12 @@ class Instrumenter {
     this._plugins.set(plugin, Object.assign({ config: {} }, meta))
   }
 
-  _validate (plugin, moduleBaseDir) {
+  _validate (plugin, moduleBaseDir, moduleVersion) {
     const meta = this._plugins.get(plugin)
     const instrumentations = [].concat(plugin)
 
     for (let i = 0; i < instrumentations.length; i++) {
+      if (instrumentations[i].versions && !matchVersion(moduleVersion, instrumentations[i].versions)) continue
       if (instrumentations[i].file && !exists(moduleBaseDir, instrumentations[i].file)) {
         this._fail(plugin)
         log.debug([

src/plugins/index.js

@@ -19,6 +19,7 @@ module.exports = {
   'mysql2': require('./mysql2'),
   'net': require('./net'),
   'pg': require('./pg'),
+  'pino': require('./pino'),
   'q': require('./q'),
   'redis': require('./redis'),
   'restify': require('./restify'),

src/plugins/pino.js

@@ -0,0 +1,77 @@
+'use strict'
+
+const tx = require('./util/log')
+
+function createWrapWrite (tracer, config) {
+  return function wrapWrite (write) {
+    return function writeWithTrace (obj, msg, num) {
+      arguments[0] = obj = obj || {}
+
+      tx.correlate(tracer, obj)
+
+      return write.apply(this, arguments)
+    }
+  }
+}
+
+function createWrapGenLog (tracer, config) {
+  return function wrapGenLog (genLog) {
+    return function genLogWithTrace (z) {
+      const log = genLog(z)
+
+      return function logWithTrace (a, b, c, d, e, f, g, h, i, j, k) {
+        const args = [a, b, c, d, e, f, g, h, i, j, k]
+
+        if (!a) {
+          args[0] = {}
+        } else if (typeof a !== 'object') {
+          args.unshift({})
+        }
+
+        tx.correlate(tracer, args[0])
+
+        return log.apply(this, args)
+      }
+    }
+  }
+}
+
+module.exports = [
+  {
+    name: 'pino',
+    versions: ['5'],
+    patch (pino, tracer, config) {
+      if (!config.correlate) return
+
+      this.wrap(Object.getPrototypeOf(pino()), pino.symbols.writeSym, createWrapWrite(tracer, config))
+    },
+    unpatch (pino) {
+      this.unwrap(Object.getPrototypeOf(pino()), pino.symbols.writeSym)
+    }
+  },
+  {
+    name: 'pino',
+    versions: ['4'],
+    file: 'lib/tools.js',
+    patch (tools, tracer, config) {
+      if (!config.correlate) return
+
+      this.wrap(tools, 'genLog', createWrapGenLog(tracer, config))
+    },
+    unpatch (tools) {
+      this.unwrap(tools, 'genLog')
+    }
+  },
+  {
+    name: 'pino',
+    versions: ['2 - 3'],
+    patch (pino, tracer, config) {
+      if (!config.correlate) return
+
+      this.wrap(Object.getPrototypeOf(pino()), 'asJson', createWrapWrite(tracer, config))
+    },
+    unpatch (pino) {
+      this.unwrap(Object.getPrototypeOf(pino()), 'asJson')
+    }
+  }
+]

test/plugins/pino.spec.js

@@ -0,0 +1,87 @@
+'use strict'
+
+const Writable = require('stream').Writable
+const agent = require('./agent')
+const plugin = require('../../src/plugins/pino')
+
+wrapIt()
+
+describe('Plugin', () => {
+  let logger
+  let tracer
+  let stream
+  let span
+
+  function setup (version) {
+    const pino = require(`../../versions/pino@${version}`).get()
+
+    span = tracer.startSpan('test')
+
+    stream = new Writable()
+    stream._write = () => {}
+
+    sinon.spy(stream, 'write')
+
+    logger = pino(stream)
+  }
+
+  describe('pino', () => {
+    withVersions(plugin, 'pino', version => {
+      beforeEach(() => {
+        tracer = require('../..')
+      })
+
+      afterEach(() => {
+        return agent.close()
+      })
+
+      describe('without configuration', () => {
+        beforeEach(() => {
+          return agent.load(plugin, 'pino')
+            .then(() => {
+              setup(version)
+            })
+        })
+
+        it('should not alter the default behavior', () => {
+          tracer.scopeManager().activate(span)
+
+          logger.info('message')
+
+          expect(stream.write).to.have.been.called
+
+          const record = JSON.parse(stream.write.firstCall.args[0].toString())
+
+          expect(record).to.not.include({
+            'dd.trace_id': span.context().toTraceId(),
+            'dd.span_id': span.context().toSpanId()
+          })
+        })
+      })
+
+      describe('with configuration', () => {
+        beforeEach(() => {
+          return agent.load(plugin, 'pino', { correlate: true })
+            .then(() => {
+              setup(version)
+            })
+        })
+
+        it('should add the trace identifiers to logger instances', () => {
+          tracer.scopeManager().activate(span)
+
+          logger.info('message')
+
+          expect(stream.write).to.have.been.called
+
+          const record = JSON.parse(stream.write.firstCall.args[0].toString())
+
+          expect(record).to.include({
+            'dd.trace_id': span.context().toTraceId(),
+            'dd.span_id': span.context().toSpanId()
+          })
+        })
+      })
+    })
+  })
+})