refactor(*): use async_hooks for Node.js 8.1.0 and above

Fixes elastic#75

Author: watson

.travis.yml

@@ -31,6 +31,14 @@ jobs:
 
   include:
 
+    # Async Hooks build stage
+    - stage: async-hooks
+      node_js: '9'
+      env: ELASTIC_APM_FF_ASYNC_HOOKS=1
+    -
+      node_js: '8'
+      env: ELASTIC_APM_FF_ASYNC_HOOKS=1
+
     # Coverage
     - stage: 'coverage'
       script:

docs/compatibility.asciidoc

@@ -7,7 +7,8 @@ Previous versions of Node.js are not supported.
 Some versions of Node.js contain bugs or issues that limit our ability to instrument them correctly.
 The following versions of Node.js are known to not be fully instrumented:
 
-- v7.10.x - Recommended solution: Upgrade to v8.0.0 or higher to get full support
+- v7.10.x - Recommended solution: Upgrade to v8.1.0 or higher to get full support
+- v8.0.0 - Recommended solution: Upgrade to v8.1.0 or higher to get full support
 
 [float]
 [[compatibility-frameworks]]

lib/agent.js

@@ -80,6 +80,7 @@ Agent.prototype._config = function (opts) {
   this._ignoreUrlRegExp = opts.ignoreUrlRegExp
   this._ignoreUserAgentStr = opts.ignoreUserAgentStr
   this._ignoreUserAgentRegExp = opts.ignoreUserAgentRegExp
+  this.ff_asyncHooks = opts.ff_asyncHooks
   this.ff_captureFrame = opts.ff_captureFrame
   this.sourceContext = opts.sourceContext
 

lib/config.js

@@ -34,6 +34,7 @@ var DEFAULTS = {
   errorOnAbortedRequests: false,
   abortedErrorThreshold: 25000,
   instrument: true,
+  ff_asyncHooks: false,
   ff_captureFrame: false,
   sourceContext: true
 }
@@ -57,6 +58,7 @@ var ENV_TABLE = {
   instrument: 'ELASTIC_APM_INSTRUMENT',
   flushInterval: 'ELASTIC_APM_FLUSH_INTERVAL',
   maxQueueSize: 'ELASTIC_APM_MAX_QUEUE_SIZE',
+  ff_asyncHooks: 'ELASTIC_APM_FF_ASYNC_HOOKS',
   ff_captureFrame: 'ELASTIC_APM_FF_CAPTURE_FRAME',
   sourceContext: 'ELASTIC_APM_SOURCE_CONTEXT'
 }
@@ -70,6 +72,7 @@ var BOOL_OPTS = [
   'logBody',
   'errorOnAbortedRequests',
   'instrument',
+  'ff_asyncHooks',
   'ff_captureFrame',
   'sourceContext'
 ]

lib/instrumentation/async-hooks.js

@@ -0,0 +1,37 @@
+'use strict'
+
+const asyncHooks = require('async_hooks')
+
+module.exports = function (ins) {
+  const asyncHook = asyncHooks.createHook({init, before, after, destroy})
+  const initState = new Map()
+  const beforeState = new Map()
+
+  asyncHook.enable()
+
+  function init (asyncId, type, triggerAsyncId, resource) {
+    // We don't care about the TIMERWRAP, as it will only init once for each
+    // timer that shares the timeout value. Instead we rely on the Timeout
+    // type, which will init for each scheduled timer.
+    if (type === 'TIMERWRAP') return
+
+    initState.set(asyncId, ins.currentTransaction)
+  }
+
+  function before (asyncId) {
+    if (!initState.has(asyncId)) return // in case type === TIMERWRAP
+    beforeState.set(asyncId, ins.currentTransaction)
+    ins.currentTransaction = initState.get(asyncId)
+  }
+
+  function after (asyncId) {
+    if (!initState.has(asyncId)) return // in case type === TIMERWRAP
+    ins.currentTransaction = beforeState.get(asyncId)
+  }
+
+  function destroy (asyncId) {
+    if (!initState.has(asyncId)) return // in case type === TIMERWRAP
+    initState.delete(asyncId)
+    beforeState.delete(asyncId)
+  }
+}

lib/instrumentation/index.js

@@ -2,6 +2,7 @@
 
 var fs = require('fs')
 var path = require('path')
+var semver = require('semver')
 var hook = require('require-in-the-middle')
 var Transaction = require('./transaction')
 var Queue = require('./queue')
@@ -40,7 +41,11 @@ Instrumentation.prototype.start = function () {
     })
   })
 
-  require('./patch-async')(this)
+  if (this._agent.ff_asyncHooks && semver.gte(process.version, '8.1.0')) {
+    require('./async-hooks')(this)
+  } else {
+    require('./patch-async')(this)
+  }
 
   debug('shimming Module._load function')
   hook(MODULES, function (exports, name, basedir) {

package.json

@@ -112,6 +112,7 @@
     "pg": "^7.1.0",
     "redis": "^2.6.3",
     "restify": "^4.3.0",
+    "send": "^0.16.1",
     "standard": "^10.0.2",
     "tape": "^4.8.0",
     "test-all-versions": "^3.1.1",

test/agent.js

@@ -26,6 +26,7 @@ var optionFixtures = [
   ['stackTraceLimit', 'STACK_TRACE_LIMIT', Infinity],
   ['captureExceptions', 'CAPTURE_EXCEPTIONS', true],
   ['instrument', 'INSTRUMENT', true],
+  ['ff_asyncHooks', 'FF_ASYNC_HOOKS', false],
   ['ff_captureFrame', 'FF_CAPTURE_FRAME', false]
 ]
 

test/instrumentation/async-hooks.js

@@ -0,0 +1,86 @@
+'use strict'
+
+var agent = require('../..').start({
+  appName: 'test',
+  captureExceptions: false,
+  ff_asyncHooks: true
+})
+var ins = agent._instrumentation
+
+var test = require('tape')
+
+test('setTimeout', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    setTimeout(function () {
+      t.equal(ins.currentTransaction, trans)
+    }, 50)
+  })
+})
+
+test('setInterval', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    var timer = setInterval(function () {
+      clearInterval(timer)
+      t.equal(ins.currentTransaction, trans)
+    }, 50)
+  })
+})
+
+test('setImmediate', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    setImmediate(function () {
+      t.equal(ins.currentTransaction, trans)
+    })
+  })
+})
+
+test('process.nextTick', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    process.nextTick(function () {
+      t.equal(ins.currentTransaction, trans)
+    })
+  })
+})
+
+test('pre-resolved promise', function (t) {
+  t.plan(4)
+
+  var p = Promise.resolve('success')
+
+  twice(function () {
+    var trans = agent.startTransaction()
+    p.then(function (result) {
+      t.equal(result, 'success')
+      t.equal(ins.currentTransaction, trans)
+    })
+  })
+})
+
+test('resolve promise', function (t) {
+  t.plan(4)
+  twice(function () {
+    var p = new Promise(function (resolve) {
+      setTimeout(function () {
+        resolve('success')
+      }, 20)
+    })
+    var trans = agent.startTransaction()
+    p.then(function (result) {
+      t.equal(result, 'success')
+      t.equal(ins.currentTransaction, trans)
+    })
+  })
+})
+
+function twice (fn) {
+  setImmediate(fn)
+  setImmediate(fn)
+}

test/instrumentation/github-issue-75.js

@@ -0,0 +1,71 @@
+'use strict'
+
+var agent = require('../..').start({
+  appName: 'test',
+  captureExceptions: false,
+  ff_asyncHooks: true
+})
+
+var http = require('http')
+var send = require('send')
+var test = require('tape')
+
+// run it 5 times in case of false positives due to race conditions
+times(5, function (n, done) {
+  test('https://github.com/elastic/apm-agent-nodejs/issues/75 ' + n, function (t) {
+    resetAgent(function (endpoint, headers, data, cb) {
+      t.equal(data.transactions.length, 2, 'should create transactions')
+      data.transactions.forEach(function (trans) {
+        t.equal(trans.traces.length, 1, 'transaction should have one trace')
+        t.equal(trans.traces[0].name, trans.id, 'trace should belong to transaction')
+      })
+      server.close()
+      t.end()
+      done()
+    })
+
+    var server = http.createServer(function (req, res) {
+      var trace = agent.buildTrace()
+      trace.start(agent._instrumentation.currentTransaction.id)
+      setTimeout(function () {
+        trace.end()
+        send(req, __filename).pipe(res)
+      }, 50)
+    })
+
+    var requestNo = 0
+
+    server.listen(function () {
+      request()
+      request()
+    })
+
+    function request () {
+      var port = server.address().port
+      http.get('http://localhost:' + port, function (res) {
+        res.on('end', function () {
+          if (++requestNo === 2) {
+            agent._instrumentation._queue._flush()
+          }
+        })
+        res.resume()
+      })
+    }
+  })
+})
+
+function times (max, fn) {
+  var n = 0
+  run()
+  function run () {
+    if (++n > max) return
+    fn(n, run)
+  }
+}
+
+function resetAgent (cb) {
+  agent._instrumentation.currentTransaction = null
+  agent._instrumentation._queue._clear()
+  agent._httpClient = { request: cb || function () {} }
+  agent.captureError = function (err) { throw err }
+}