fix: ensure the span run-context for output http requests does not sp…

…ill into user code

This fixes the 'http' and 'https' instrumentation for outgoing requests
to not have the 'http' span context be active in user code. This ensures
that user code cannot create a child span of the http span, which would
(a) be misleading and (b) cause problems for coming exit span and
compressed span work.

Refs: #2430

examples/trace-http-request.js

@@ -0,0 +1,47 @@
+#!/usr/bin/env node --unhandled-rejections=strict
+
+// A small example showing Elastic APM tracing outgoing HTTP requests using
+// `http.request` (or `http.get`, `https.request`, `https.get`) from Node.js
+// core.
+
+const apm = require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-http-request',
+  // Now that OpenTelemetry has been GA for a while, the Elastic-specific
+  // 'elastic-apm-traceparent' header is rarely needed.
+  useElasticTraceparentHeader: false
+})
+
+const http = require('http')
+
+function makeARequest (url, opts, cb) {
+  const clientReq = http.request(url, opts, function (clientRes) {
+    console.log('client response: %s %s', clientRes.statusCode, clientRes.headers)
+
+    const chunks = []
+    clientRes.on('data', function (chunk) {
+      chunks.push(chunk)
+    })
+
+    clientRes.on('end', function () {
+      const body = chunks.join('')
+      console.log('client response body: %j', body)
+      cb()
+    })
+  })
+
+  clientReq.end()
+}
+
+// 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')
+makeARequest(
+  'http://httpstat.us/200',
+  { headers: { accept: '*/*' } },
+  function () {
+    t0.end()
+  }
+)

examples/trace-http.js

@@ -0,0 +1,66 @@
+#!/usr/bin/env node --unhandled-rejections=strict
+
+// A small example showing Elastic APM tracing of the core 'http' module.
+//
+// 1. This creates an HTTP server listening at http://localhost:3000
+// 2. For any incoming request it makes an outgoing HTTPS request to
+//    'https://httpstat.us/200'.
+// 3. Calls the created HTTP server to trigger the above request handling.
+//
+// We expect the APM agent to automatically generate tracing data for (1) and (2).
+
+require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-http',
+  useElasticTraceparentHeader: false,
+  // 'usePathAsTransactionName' can be useful when not using a web framework
+  // with a router. See the following for details:
+  // https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-stack.html#custom-stack-route-naming
+  usePathAsTransactionName: true
+})
+
+const http = require('http')
+const https = require('https')
+
+const server = http.createServer(function onRequest (req, res) {
+  console.log('incoming request: %s %s %s', req.method, req.url, req.headers)
+
+  req.resume()
+
+  req.on('end', function () {
+    // Make a client request to httpstat.us.
+    https.get('https://httpstat.us/200', function (cRes) {
+      console.log('httpstat.us response: %s %s', cRes.statusCode, cRes.headers)
+      cRes.resume()
+      cRes.on('end', function () {
+        // Then reply to the incoming request.
+        const resBody = 'pong'
+        res.writeHead(200, {
+          server: 'example-trace-http',
+          'content-type': 'text/plain',
+          'content-length': Buffer.byteLength(resBody)
+        })
+        res.end(resBody)
+      })
+    })
+  })
+})
+
+server.listen(3000, function () {
+  // Make a request to our HTTP server listening at http://localhost:3000.
+  //
+  // Note that this there is no current "transaction" here, so this HTTP
+  // request is not captured by APM. See "trace-http-request.js" for more.
+  const clientReq = http.request('http://localhost:3000/', function (clientRes) {
+    console.log('client response: %s %s', clientRes.statusCode, clientRes.headers)
+    const chunks = []
+    clientRes.on('data', function (chunk) {
+      chunks.push(chunk)
+    })
+    clientRes.on('end', function () {
+      const body = chunks.join('')
+      console.log('client response body: %j', body)
+      server.close()
+    })
+  })
+  clientReq.end()
+})

lib/instrumentation/http-shared.js

@@ -128,9 +128,8 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
 
   return function (orig) {
     return function (...args) {
-      // TODO: See if we can delay the creation of span until the `response`
-      // event is fired, while still having it have the correct stack trace
-      var span = agent.startSpan(null, 'external', 'http')
+      const parentRunContext = ins.currRunContext()
+      var span = ins.createSpan(null, 'external', 'http')
       var id = span && span.transaction.id
 
       agent.logger.debug('intercepted call to %s.%s %o', moduleName, method, { id: id })
@@ -139,7 +138,7 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       var newArgs = [options]
       for (const arg of args) {
         if (typeof arg === 'function') {
-          newArgs.push(arg)
+          newArgs.push(ins.bindFunctionToRunContext(parentRunContext, arg))
         } else {
           Object.assign(options, ensureUrl(arg))
         }
@@ -170,8 +169,11 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
         options.headers = newHeaders
       }
 
-      var req = orig.apply(this, newArgs)
-      if (!span) return req
+      const spanRunContext = parentRunContext.enterSpan(span)
+      var req = ins.withRunContext(spanRunContext, orig, this, ...newArgs)
+      if (!span) {
+        return req
+      }
 
       var protocol = req.agent && req.agent.protocol
       agent.logger.debug('request details: %o', { protocol: protocol, host: getSafeHost(req), id: id })
@@ -186,7 +188,7 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       // is added instead of when `response` is emitted.
       const emit = req.emit
       req.emit = function wrappedEmit (type, res) {
-        if (type === 'response') onresponse(res)
+        if (type === 'response') onResponse(res)
         if (type === 'abort') onAbort(type)
         return emit.apply(req, arguments)
       }
@@ -231,9 +233,9 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
         span.end()
       }
 
-      function onresponse (res) {
+      function onResponse (res) {
         agent.logger.debug('intercepted http.ClientRequest response event %o', { id: id })
-        ins.bindEmitter(res)
+        ins.bindEmitterToRunContext(parentRunContext, res)
         statusCode = res.statusCode
         res.prependListener('end', function () {
           agent.logger.debug('intercepted http.IncomingMessage end event %o', { id: id })

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) {

test/instrumentation/modules/http/fixtures/make-http-request.js

@@ -0,0 +1,69 @@
+// Make an `http.request(...)` and assert expected run context in all the
+// various callbacks and event handlers.
+
+const apm = require('../../../../../').start({ // elastic-apm-node
+  captureExceptions: false,
+  captureSpanStackTraces: false,
+  metricsInterval: 0,
+  cloudProvider: 'none',
+  centralConfig: false,
+  // ^^ Boilerplate config above this line is to focus on just tracing.
+  serviceName: 'run-context-http-request'
+})
+
+let assert = require('assert')
+if (Number(process.versions.node.split('.')[0]) > 8) {
+  assert = assert.strict
+}
+const http = require('http')
+
+function makeARequest (url, opts, cb) {
+  const clientReq = http.request(url, opts, function (clientRes) {
+    console.log('client response: %s %s', clientRes.statusCode, clientRes.headers)
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-http.request-callback').end()
+
+    const chunks = []
+    clientRes.on('data', function (chunk) {
+      assert(apm.currentSpan === null)
+      apm.startSpan('span-in-clientRes-on-data').end()
+      chunks.push(chunk)
+    })
+
+    clientRes.on('end', function () {
+      assert(apm.currentSpan === null)
+      apm.startSpan('span-in-clientRes-on-end').end()
+      const body = chunks.join('')
+      console.log('client response body: %j', body)
+      cb()
+    })
+  })
+
+  assert(apm.currentSpan === null)
+  apm.startSpan('span-sync-after-http.request').end()
+
+  clientReq.on('socket', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-socket').end()
+  })
+
+  clientReq.on('response', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-response').end()
+  })
+
+  clientReq.on('finish', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-finish').end()
+  })
+
+  clientReq.end()
+}
+
+const t0 = apm.startTransaction('t0')
+makeARequest(
+  'http://httpstat.us/200',
+  { headers: { accept: '*/*' } },
+  function () {
+    t0.end()
+  })

test/instrumentation/modules/http/fixtures/make-https-request.js

@@ -0,0 +1,69 @@
+// Make an `https.request(...)` and assert expected run context in all the
+// various callbacks and event handlers.
+
+const apm = require('../../../../../').start({ // elastic-apm-node
+  captureExceptions: false,
+  captureSpanStackTraces: false,
+  metricsInterval: 0,
+  cloudProvider: 'none',
+  centralConfig: false,
+  // ^^ Boilerplate config above this line is to focus on just tracing.
+  serviceName: 'run-context-https-request'
+})
+
+let assert = require('assert')
+if (Number(process.versions.node.split('.')[0]) > 8) {
+  assert = assert.strict
+}
+const https = require('https')
+
+function makeARequest (url, opts, cb) {
+  const clientReq = https.request(url, opts, function (clientRes) {
+    console.log('client response: %s %s', clientRes.statusCode, clientRes.headers)
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-https.request-callback').end()
+
+    const chunks = []
+    clientRes.on('data', function (chunk) {
+      assert(apm.currentSpan === null)
+      apm.startSpan('span-in-clientRes-on-data').end()
+      chunks.push(chunk)
+    })
+
+    clientRes.on('end', function () {
+      assert(apm.currentSpan === null)
+      apm.startSpan('span-in-clientRes-on-end').end()
+      const body = chunks.join('')
+      console.log('client response body: %j', body)
+      cb()
+    })
+  })
+
+  assert(apm.currentSpan === null)
+  apm.startSpan('span-sync-after-https.request').end()
+
+  clientReq.on('socket', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-socket').end()
+  })
+
+  clientReq.on('response', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-response').end()
+  })
+
+  clientReq.on('finish', function () {
+    assert(apm.currentSpan === null)
+    apm.startSpan('span-in-clientReq-on-finish').end()
+  })
+
+  clientReq.end()
+}
+
+const t0 = apm.startTransaction('t0')
+makeARequest(
+  'https://httpstat.us/200',
+  { headers: { accept: '*/*' } },
+  function () {
+    t0.end()
+  })