Skip to content

Commit

Permalink
fix: ensure the span run-context for outgoing http requests does not …
Browse files Browse the repository at this point in the history
…spill into user code (#2470)

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.

Also, fix a bug in the https instrumentation in older versions of node
(version <9.0.0) where the instrumentation of `https.request` relied on
intercepting `http.request` (that Node's `https.request()` would call). 
The agent didn't guarantee that the 'http' module was instrumented. 
A user program that used `https.request` without indirectly
`require('http')`ing would not get an HTTP span.

Refs: #2430
  • Loading branch information
trentm authored Dec 1, 2021
1 parent c6e5da3 commit 751b9b2
Show file tree
Hide file tree
Showing 10 changed files with 400 additions and 13 deletions.
3 changes: 3 additions & 0 deletions CHANGELOG.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,9 @@ Notes:
[float]
===== Bug fixes
* Fix 'http' and 'https' instrumentation for outgoing requests to not have the
'http' span context be active in user code. ({pull}2470[#2470])
* Fixes for 'ioredis' instrumentation ({pull}2460[#2460]):
+
** Fix run-context so that a span created in the same tick as an ioredis
Expand Down
47 changes: 47 additions & 0 deletions examples/trace-http-request.js
Original file line number Diff line number Diff line change
@@ -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()
}
)
66 changes: 66 additions & 0 deletions examples/trace-http.js
Original file line number Diff line number Diff line change
@@ -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()
})
13 changes: 9 additions & 4 deletions lib/http-request.js
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,11 @@

const { URL } = require('url')

// Getting handles on these `.request()` functions at the top-level ensures
// that we have *un*instrumented functions for internal HTTP request usage.
const coreHttpRequest = require('http').request
const coreHttpsRequest = require('https').request

// From https://github.com/nodejs/node/blob/v14.15.4/lib/internal/url.js#L1267-L1289
// for node v8 support.
//
Expand Down Expand Up @@ -104,16 +109,16 @@ function httpRequest (url, opts, cb) {
const mergedOpts = Object.assign(urlToOptions(u), otherOpts)

// http or https
let proto
let requestFn
if (mergedOpts.protocol === 'http:') {
proto = require('http')
requestFn = coreHttpRequest
} else if (mergedOpts.protocol === 'https:') {
proto = require('https')
requestFn = coreHttpsRequest
} else {
throw new Error(`unsupported protocol: "${mergedOpts.protocol}"`)
}

const req = proto.request(mergedOpts, cb)
const req = requestFn(mergedOpts, cb)

if (connectTimeout) {
// Handle a connection timeout with a timer starting when the request
Expand Down
21 changes: 12 additions & 9 deletions lib/instrumentation/http-shared.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 })
Expand All @@ -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))
}
Expand Down Expand Up @@ -170,8 +169,12 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
options.headers = newHeaders
}

var req = orig.apply(this, newArgs)
if (!span) return req
if (!span) {
return orig.apply(this, newArgs)
}

const spanRunContext = parentRunContext.enterSpan(span)
var req = ins.withRunContext(spanRunContext, orig, this, ...newArgs)

var protocol = req.agent && req.agent.protocol
agent.logger.debug('request details: %o', { protocol: protocol, host: getSafeHost(req), id: id })
Expand All @@ -186,7 +189,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)
}
Expand Down Expand Up @@ -231,9 +234,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 })
Expand Down
8 changes: 8 additions & 0 deletions lib/instrumentation/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
4 changes: 4 additions & 0 deletions lib/instrumentation/modules/https.js
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,10 @@ module.exports = function (https, agent, { version, enabled }) {

agent.logger.debug('shimming https.get function')
shimmer.wrap(https, 'get', httpShared.traceOutgoingRequest(agent, 'https', 'get'))
} else {
// We must ensure that the `http` module is instrumented to intercept
// `http.{request,get}` that `https.{request,get}` are using.
require('http')
}

return https
Expand Down
73 changes: 73 additions & 0 deletions test/instrumentation/modules/http/fixtures/make-http-request.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,73 @@
// 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 (opts, cb) {
const clientReq = http.request(opts, function (clientRes) {
console.log('client response: %s %o', 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'
host: 'httpstat.us',
path: '/200',
headers: { accept: '*/*' }
},
function () {
t0.end()
})
73 changes: 73 additions & 0 deletions test/instrumentation/modules/http/fixtures/make-https-request.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,73 @@
// 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 (opts, cb) {
const clientReq = https.request(opts, function (clientRes) {
console.log('client response: %s %o', 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'
host: 'httpstat.us',
path: '/200',
headers: { accept: '*/*' }
},
function () {
t0.end()
})
Loading

0 comments on commit 751b9b2

Please sign in to comment.