Use async_hooks for Node.js 8.2.0 and above (#77)

.travis.yml

@@ -35,6 +35,14 @@ jobs:
     #                TEST STAGE               #
     ###########################################
 
+    # Disable Async Hooks
+    -
+      node_js: '9'
+      env: ELASTIC_APM_ASYNC_HOOKS=0
+    -
+      node_js: '8'
+      env: ELASTIC_APM_ASYNC_HOOKS=0
+
     # Docs
     -
       script: npm run docs

docs/agent-api.asciidoc

@@ -150,6 +150,21 @@ A boolean specifying if the agent should collect performance metrics for the app
 
 Note that both `active` and `instrument` needs to be `true` for instrumentation to be running.
 
+[[async-hooks]]
+===== `asyncHooks`
+
+* *Type:* Boolean
+* *Default:* `true`
+* *Env:* `ELASTIC_APM_ASYNC_HOOKS`
+
+A boolean specifying if the agent should use the experimental https://nodejs.org/api/async_hooks.html[Async Hooks] API found in Node.js version 8.2.0 and above.
+This setting have no effect when running a Node.js version older than 8.2.0.
+
+If you experience any issues related to using Async Hooks,
+please https://github.com/elastic/apm-agent-nodejs/issues[open an issue].
+
+Note that not all core Node.js API's can be instrumented without the use of Async Hooks if running Node.js 8 or above.
+
 [[ignore-urls]]
 ===== `ignoreUrls`
 

docs/compatibility.asciidoc

@@ -7,7 +7,15 @@ 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.2.0 or higher to get full support
+- v8.0.x - Recommended solution: Upgrade to v8.2.0 or higher to get full support
+- v8.1.x - Recommended solution: Upgrade to v8.2.0 or higher to get full support
+
+NOTE: Support for Node.js 8.2.0 and above is experimental as it makes use the experimental core API https://nodejs.org/api/async_hooks.html[Async Hooks].
+If you experience any issues related to using Async Hooks,
+you can always disable the use of this API by setting the <<async-hooks,`asyncHooks`>> config option to `false`.
+Note however,
+that not all core Node.js API's can be instrumented without the use of Async Hooks if running Node.js 8 or above.
 
 [float]
 [[compatibility-frameworks]]

lib/config.js

@@ -34,6 +34,7 @@ var DEFAULTS = {
   errorOnAbortedRequests: false,
   abortedErrorThreshold: 25000,
   instrument: true,
+  asyncHooks: true,
   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',
+  asyncHooks: 'ELASTIC_APM_ASYNC_HOOKS',
   ff_captureFrame: 'ELASTIC_APM_FF_CAPTURE_FRAME',
   sourceContext: 'ELASTIC_APM_SOURCE_CONTEXT'
 }
@@ -70,6 +72,7 @@ var BOOL_OPTS = [
   'logBody',
   'errorOnAbortedRequests',
   'instrument',
+  'asyncHooks',
   'ff_captureFrame',
   'sourceContext'
 ]

lib/instrumentation/async-hooks.js

@@ -0,0 +1,35 @@
+'use strict'
+
+const asyncHooks = require('async_hooks')
+
+module.exports = function (ins) {
+  const asyncHook = asyncHooks.createHook({init, destroy})
+  const transactions = new Map()
+
+  Object.defineProperty(ins, 'currentTransaction', {
+    get: function () {
+      const asyncId = asyncHooks.executionAsyncId()
+      return transactions.has(asyncId) ? transactions.get(asyncId) : null
+    },
+    set: function (trans) {
+      const asyncId = asyncHooks.executionAsyncId()
+      transactions.set(asyncId, trans)
+    }
+  })
+
+  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
+
+    transactions.set(asyncId, ins.currentTransaction)
+  }
+
+  function destroy (asyncId) {
+    if (!transactions.has(asyncId)) return // in case type === TIMERWRAP
+    transactions.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._conf.asyncHooks && semver.gte(process.version, '8.2.0')) {
+    require('./async-hooks')(this)
+  } else {
+    require('./patch-async')(this)
+  }
 
   debug('shimming Module._load function')
   hook(MODULES, function (exports, name, basedir) {

package.json

@@ -17,7 +17,7 @@
     "test": "npm run check && node test/test.js",
     "posttest": "test/posttest.sh",
     "test-cli": "node test/script/cli.js",
-    "test-deps": "dependency-check . && dependency-check . --unused --no-dev --entry lib/instrumentation/modules/*"
+    "test-deps": "dependency-check . -i async_hooks && dependency-check . --unused --no-dev --entry lib/instrumentation/modules/*"
   },
   "directories": {
     "test": "test"
@@ -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],
+  ['asyncHooks', 'ASYNC_HOOKS', true],
   ['ff_captureFrame', 'FF_CAPTURE_FRAME', false]
 ]
 

test/instrumentation/async-hooks.js

@@ -0,0 +1,120 @@
+'use strict'
+
+var agent = require('../..').start({
+  appName: 'test',
+  captureExceptions: false,
+  asyncHooks: true
+})
+var ins = agent._instrumentation
+
+var test = require('tape')
+var semver = require('semver')
+
+test('setTimeout', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    setTimeout(function () {
+      t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+    }, 50)
+  })
+})
+
+test('setInterval', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    var timer = setInterval(function () {
+      clearInterval(timer)
+      t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+    }, 50)
+  })
+})
+
+test('setImmediate', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    setImmediate(function () {
+      t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+    })
+  })
+})
+
+test('process.nextTick', function (t) {
+  t.plan(2)
+  twice(function () {
+    var trans = agent.startTransaction()
+    process.nextTick(function () {
+      t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+    })
+  })
+})
+
+// We can't instrument ore-defined promises properly without async-hooks, so
+// lets not run these tests on versions of Node.js without async-hooks
+if (semver.gte(process.version, '8.2.0')) {
+  test('pre-defined, pre-resolved shared 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 && ins.currentTransaction.id, trans.id)
+      })
+    })
+  })
+
+  test('pre-defined, pre-resolved non-shared promise', function (t) {
+    t.plan(4)
+
+    twice(function () {
+      var p = Promise.resolve('success')
+      var trans = agent.startTransaction()
+      p.then(function (result) {
+        t.equal(result, 'success')
+        t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+      })
+    })
+  })
+
+  test('pre-defined, post-resolved 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 && ins.currentTransaction.id, trans.id)
+      })
+    })
+  })
+}
+
+test('post-defined, post-resolved promise', function (t) {
+  t.plan(4)
+  twice(function () {
+    var trans = agent.startTransaction()
+    var p = new Promise(function (resolve) {
+      setTimeout(function () {
+        resolve('success')
+      }, 20)
+    })
+    p.then(function (result) {
+      t.equal(result, 'success')
+      t.equal(ins.currentTransaction && ins.currentTransaction.id, trans.id)
+    })
+  })
+})
+
+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,
+  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 }
+}