Use async_hooks for Node.js 8.2.0 and above

.travis.yml

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

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/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,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.get(asyncId)
+    },
+    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.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

@@ -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],
+  ['ff_asyncHooks', 'FF_ASYNC_HOOKS', false],
   ['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,
+  ff_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.1.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,
+  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 }
+}