fix: run-context for 'http2.request' instrumentation

Refs: #2430

CHANGELOG.asciidoc

@@ -39,6 +39,9 @@ Notes:
 [float]
 ===== Bug fixes
 
+* Fix 'http2' instrumentation for outgoing requests to not have the created
+  HTTP span context be active in user code.
+
 * Fixes for 'ioredis' instrumentation ({pull}2460[#2460]):
 +
 **  Fix run-context so that a span created in the same tick as an ioredis

examples/trace-http2-request.js

@@ -0,0 +1,37 @@
+#!/usr/bin/env node --unhandled-rejections=strict
+
+// A small example showing Elastic APM tracing outgoing HTTP/2 requests
+// (i.e. `http2.request`).
+
+const apm = require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-http2-request'
+})
+
+const http2 = require('http2')
+const { HTTP2_HEADER_PATH } = http2.constants
+
+const session = http2.connect('https://httpstat.us')
+
+// For tracing spans to be created, there must be an active transaction.
+// Typically, a transaction is automatically started for incoming HTTP
+// requests to a Node.js server. However, because this script is not running
+// an HTTP server, we manually start a transaction. More details at:
+// https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html
+const t0 = apm.startTransaction('t0')
+
+const req = session.request({
+  [HTTP2_HEADER_PATH]: '/200',
+  accept: '*/*'
+})
+req.on('response', (headers) => {
+  console.log('client response:', headers)
+})
+req.setEncoding('utf8')
+req.on('data', (chunk) => {
+  console.log('data chunk:', chunk)
+})
+req.on('end', () => {
+  console.log('req end')
+  t0.end()
+  session.close()
+})

lib/instrumentation/index.js

@@ -489,6 +489,14 @@ Instrumentation.prototype.bindEmitter = function (ee) {
   return this._runCtxMgr.bindEE(this._runCtxMgr.active(), ee)
 }
 
+// Bind the given EventEmitter to a given run context.
+Instrumentation.prototype.bindEmitterToRunContext = function (runContext, ee) {
+  if (!this._started) {
+    return ee
+  }
+  return this._runCtxMgr.bindEE(runContext, ee)
+}
+
 // Return true iff the given EventEmitter is bound to a run context.
 Instrumentation.prototype.isEventEmitterBound = function (ee) {
   if (!this._started) {

lib/instrumentation/modules/http2.js

@@ -206,16 +206,18 @@ module.exports = function (http2, agent, { enabled }) {
 
   function wrapRequest (orig, host) {
     return function (headers) {
+      agent.logger.debug('intercepted call to http2.request')
       var method = headers[':method'] || 'GET'
-      var span = agent.startSpan(null, 'external', 'http', method)
-      var id = span && span.transaction.id
-
-      agent.logger.debug('intercepted call to http2.request %o', { id })
+      const span = ins.createSpan(null, 'external', 'http', method)
+      if (!span) {
+        return orig.apply(this, arguments)
+      }
 
-      var req = orig.apply(this, arguments)
-      if (!span) return req
+      const parentRunContext = ins.currRunContext()
+      const spanRunContext = parentRunContext.enterSpan(span)
+      var req = ins.withRunContext(spanRunContext, orig, this, ...arguments)
 
-      ins.bindEmitter(req)
+      ins.bindEmitterToRunContext(parentRunContext, req)
 
       var urlObj = parseUrl(headers[':path'])
       var path = urlObj.pathname
@@ -228,7 +230,7 @@ module.exports = function (http2, agent, { enabled }) {
       })
 
       req.on('end', () => {
-        agent.logger.debug('intercepted http2 client end event %o', { id })
+        agent.logger.debug('intercepted http2 client end event')
 
         span.setHttpContext({
           method,

test/instrumentation/modules/http2.test.js

@@ -278,7 +278,7 @@ isSecure.forEach(secure => {
   })
 
   test(`http2.request${secure ? ' secure' : ' '}`, t => {
-    t.plan(36)
+    t.plan(38)
 
     resetAgent(3, (data) => {
       t.strictEqual(data.transactions.length, 2)
@@ -339,7 +339,11 @@ isSecure.forEach(secure => {
         })
 
         var req = client.request({ ':path': '/sub' })
-        req.on('end', () => client.destroy())
+        t.ok(agent.currentSpan === null, 'the http2 span should not spill into user code')
+        req.on('end', () => {
+          t.ok(agent.currentSpan === null, 'the http2 span should *not* be the currentSpan in user event handlers')
+          client.destroy()
+        })
         req.pipe(stream)
       } else {
         stream.respond({