Skip to content
This repository has been archived by the owner on Aug 4, 2023. It is now read-only.

fix: do not trace APM server client requests #161

Merged
merged 2 commits into from
Aug 16, 2021

Conversation

trentm
Copy link
Member

@trentm trentm commented Aug 10, 2021

Use uninstrumented https.request() et al (grabbing references before the
agent does shimming) for requests to APM server. This avoids them
interfering in tracing (adding trace-context headers to APM server
requests, emitting debug logs about spans). This will fix
elastic/apm-agent-nodejs#1995

Use uninstrumented https.request() et al (grabbing references before the
agent does shimming) for requests to APM server. This avoids them
interfering in tracing (adding trace-context headers to APM server
requests, emitting debug logs about spans). This will fix
elastic/apm-agent-nodejs#1995
@trentm trentm requested a review from astorm August 10, 2021 19:25
@trentm trentm self-assigned this Aug 10, 2021
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Aug 10, 2021
@trentm
Copy link
Member Author

trentm commented Aug 10, 2021

before:

% node example-do-not-trace-http-client.js | ecslog
[2021-08-10T19:17:41.481Z] DEBUG (elastic-apm-node): no cloud metadata servers responded
[2021-08-10T19:17:41.483Z] DEBUG (elastic-apm-node): adding hook to Node.js module loader
[2021-08-10T19:17:41.484Z] DEBUG (elastic-apm-node): shimming [email protected] module
[2021-08-10T19:17:41.486Z] DEBUG (elastic-apm-node): shimming http.Server.prototype.emit function
[2021-08-10T19:17:41.486Z] DEBUG (elastic-apm-node): shimming http.ServerResponse.prototype.writeHead function
[2021-08-10T19:17:41.486Z] DEBUG (elastic-apm-node): shimming http.request function
[2021-08-10T19:17:41.486Z] DEBUG (elastic-apm-node): shimming http.get function
[2021-08-10T19:17:41.486Z] DEBUG (elastic-apm-node): shimming [email protected] module
[2021-08-10T19:17:41.490Z] DEBUG (elastic-apm-node): shimming https.Server.prototype.emit function
[2021-08-10T19:17:41.490Z] DEBUG (elastic-apm-node): shimming https.request function
[2021-08-10T19:17:41.490Z] DEBUG (elastic-apm-node): shimming https.get function
[2021-08-10T19:17:41.492Z] DEBUG (elastic-apm-node): start trace {"trans":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","name":"unnamed","type":null,"subtype":null,"action":null}
[2021-08-10T19:17:41.493Z] DEBUG (elastic-apm-node): start span {"span":"7427cfd879b8b602","parent":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","name":"s2","type":null,"subtype":null,"action":null}
[2021-08-10T19:17:41.494Z] DEBUG (elastic-apm-node): ended span {"span":"7427cfd879b8b602","parent":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","name":"s2","type":null,"subtype":null,"action":null}
[2021-08-10T19:17:41.494Z] DEBUG (elastic-apm-node): encoding span {"span":"7427cfd879b8b602","parent":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","name":"s2","type":null}
[2021-08-10T19:17:41.495Z] DEBUG (elastic-apm-node): sending transaction {"trans":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835"}
[2021-08-10T19:17:41.495Z] DEBUG (elastic-apm-node): ended transaction {"trans":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","type":null,"result":"success","name":"t1"}
[2021-08-10T19:17:41.495Z] DEBUG (elastic-apm-node): sending span {"span":"7427cfd879b8b602","parent":"123881bef54b0b44","trace":"6aec6e52d0d2adb8356bc434db628835","name":"s2","type":null}
[2021-08-10T19:17:41.519Z] DEBUG (elastic-apm-node): no active transaction found - cannot build new span
[2021-08-10T19:17:41.519Z] DEBUG (elastic-apm-node): intercepted call to http.request {"id":null}

after:

% node example-do-not-trace-http-client.js | ecslog
[2021-08-10T19:19:11.903Z] DEBUG (elastic-apm-node): no cloud metadata servers responded
[2021-08-10T19:19:11.905Z] DEBUG (elastic-apm-node): adding hook to Node.js module loader
[2021-08-10T19:19:11.906Z] DEBUG (elastic-apm-node): shimming [email protected] module
[2021-08-10T19:19:11.908Z] DEBUG (elastic-apm-node): shimming http.Server.prototype.emit function
[2021-08-10T19:19:11.908Z] DEBUG (elastic-apm-node): shimming http.ServerResponse.prototype.writeHead function
[2021-08-10T19:19:11.908Z] DEBUG (elastic-apm-node): shimming http.request function
[2021-08-10T19:19:11.909Z] DEBUG (elastic-apm-node): shimming http.get function
[2021-08-10T19:19:11.909Z] DEBUG (elastic-apm-node): shimming [email protected] module
[2021-08-10T19:19:11.911Z] DEBUG (elastic-apm-node): shimming https.Server.prototype.emit function
[2021-08-10T19:19:11.912Z] DEBUG (elastic-apm-node): shimming https.request function
[2021-08-10T19:19:11.912Z] DEBUG (elastic-apm-node): shimming https.get function
[2021-08-10T19:19:11.913Z] DEBUG (elastic-apm-node): start trace {"trans":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","name":"unnamed","type":null,"subtype":null,"action":null}
[2021-08-10T19:19:11.914Z] DEBUG (elastic-apm-node): start span {"span":"9f5bc809737765db","parent":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","name":"s2","type":null,"subtype":null,"action":null}
[2021-08-10T19:19:11.915Z] DEBUG (elastic-apm-node): ended span {"span":"9f5bc809737765db","parent":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","name":"s2","type":null,"subtype":null,"action":null}
[2021-08-10T19:19:11.915Z] DEBUG (elastic-apm-node): encoding span {"span":"9f5bc809737765db","parent":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","name":"s2","type":null}
[2021-08-10T19:19:11.916Z] DEBUG (elastic-apm-node): sending transaction {"trans":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48"}
[2021-08-10T19:19:11.916Z] DEBUG (elastic-apm-node): ended transaction {"trans":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","type":null,"result":"success","name":"t1"}
[2021-08-10T19:19:11.916Z] DEBUG (elastic-apm-node): sending span {"span":"9f5bc809737765db","parent":"c34c63705f435321","trace":"0dcc97819df7f66bb27a2edd38225b48","name":"s2","type":null}

Note these two log debug lines are now gone:

[2021-08-10T19:17:41.519Z] DEBUG (elastic-apm-node): no active transaction found - cannot build new span
[2021-08-10T19:17:41.519Z] DEBUG (elastic-apm-node): intercepted call to http.request {"id":null}

using this example script:

var apm = require('./').start({ // elastic-apm-node
  captureExceptions: false,
  logUncaughtExceptions: true,
  captureSpanStackTraces: false,
  stackTraceLimit: 3,
  apiRequestTime: 3,
  metricsInterval: 0,
  cloudProvider: 'none',
  // ^^ Boilerplate config above this line is to focus on just tracing.
  serviceName: 'example-do-not-trace-http-client',
  centralConfig: false, // TODO test central config is also not traced
  // asyncHooks: false, // TODO test with and without asyncHooks
  logLevel: 'debug'
})

// Explicitly require the possible APM server client transport modules so that
// the agent instruments them.
var http = require('http')
var https = require('https')

var t1 = apm.startTransaction('t1')
setImmediate(function () {
  var s2 = apm.startSpan('s2')
  setImmediate(function () {
    s2.end()
    t1.end()
  })
})

@trentm
Copy link
Member Author

trentm commented Aug 10, 2021

If this sounds reasonable, then I'll test a bit more (with/without asyncHooks; test the central config requests), then pull this out of draft.

Then I'll follow up with an agent change that uses this new http-client version and drops the special-case handling that attempts to hide the instrumentation of APM server requests:

diff --git a/lib/instrumentation/http-shared.js b/lib/instrumentation/http-shared.js
index 6b97de97..6bea384d 100644
--- a/lib/instrumentation/http-shared.js
+++ b/lib/instrumentation/http-shared.js
@@ -169,13 +169,8 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       var req = orig.apply(this, newArgs)
       if (!span) return req

-      if (getSafeHost(req) === agent._conf.serverHost) {
-        agent.logger.debug('ignore %s request to intake API %o', moduleName, { id: id })
-        return req
-      } else {
-        var protocol = req.agent && req.agent.protocol
-        agent.logger.debug('request details: %o', { protocol: protocol, host: getSafeHost(req), id: id })
-      }
+      var protocol = req.agent && req.agent.protocol
+      agent.logger.debug('request details: %o', { protocol: protocol, host: getSafeHost(req), id: id })

       ins.bindEmitter(req)

@apmmachine
Copy link

apmmachine commented Aug 10, 2021

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts preview preview

Expand to view the summary

Build stats

  • Start Time: 2021-08-12T22:07:11.916+0000

  • Duration: 7 min 56 sec

  • Commit: 7b38b62

Test stats 🧪

Test Results
Failed 0
Passed 16975
Skipped 0
Total 16975

Trends 🧪

Image of Build Times

Image of Tests

@trentm
Copy link
Member Author

trentm commented Aug 10, 2021

Oh, also relevant from those before and after examples are the headers sent to APM server.

before:

[2021-08-10T18:54:21.599Z]  INFO: mockapmserver/37402 on pink.local: request (req.remoteAddress=::ffff:127.0.0.1, req.remotePort=54103, req.bodyLength=1096, res.bodyLength=2)
    POST /intake/v2/events HTTP/1.1
    accept: application/json
    user-agent: elasticapm-node/3.19.0 elastic-apm-http-client/9.8.1 node/12.22.1
    content-type: application/x-ndjson
    content-encoding: gzip
    traceparent: 00-24d9757287db0ab460070884580ee67a-91dda625aacc82c8-01
    tracestate: es=s:1
    elastic-apm-traceparent: 00-24d9757287db0ab460070884580ee67a-91dda625aacc82c8-01
    host: localhost:8200
    connection: keep-alive
    transfer-encoding: chunked

Note that trace-context headers being unintentionally sent.

after:

[2021-08-10T18:55:23.360Z]  INFO: mockapmserver/37402 on pink.local: request (req.remoteAddress=::ffff:127.0.0.1, req.remotePort=54118, req.bodyLength=1097, res.bodyLength=2)
    POST /intake/v2/events HTTP/1.1
    accept: application/json
    user-agent: elasticapm-node/3.19.0 elastic-apm-http-client/9.8.1 node/12.22.1
    content-type: application/x-ndjson
    content-encoding: gzip
    host: localhost:8200
    connection: keep-alive
    transfer-encoding: chunked

Copy link
Contributor

@astorm astorm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Overall looks like a reasonable approach. 👍 Stream of conscious notes/review follows

I see that we're stashing the original values of of get and request from the http and https in module-global variables and then using these for our requests to APM Server.

Not an issue, but worth asking/noting: This works because the agent loads the client module (var ElasticAPMHttpClient = require('elastic-apm-http-client')) before it does its monkey patching, right?

The elastic-apm-http-client also references the Agent transport --

this._agent = new this._transport.Agent(agentOpts)

but I don't think we need to change anything here.

@trentm
Copy link
Member Author

trentm commented Aug 10, 2021

Not an issue, but worth asking/noting: This works because the agent loads the client module (var ElasticAPMHttpClient = require('elastic-apm-http-client')) before it does its monkey patching, right?

Yes, exactly. That require statement happens when the agent itself is required. The monkey-patching of modules doesn't happen until after agent.start() sometime. This ordering is reasonably future-proof.

The elastic-apm-http-client also references the Agent transport ... but I don't think we need to change anything here.

Yup. Currently http.Agent isn't wrapped for anything. Theoretically a future agent change could change how the http/https modules are instrumented such that this could break... but I'll try to have a test case in the agent that would catch a span for the agent comms getting erroneously included.

@trentm trentm marked this pull request as ready for review August 12, 2021 22:07
@trentm trentm requested a review from astorm August 12, 2021 22:07
@trentm
Copy link
Member Author

trentm commented Aug 12, 2021

@astorm I'm re-requesting review. I'll want a release for the agent immediately, so I'm bumping the version.

I don't know what meaningful testing I can do from the http-client side, so I haven't added any. I could use Object.getOwnPropertySymbols on client._transportRequest after it is configured to ensure ... it doesn't have symbols like these:

[ Symbol(elasticAPMIsWrapped), Symbol(ElasticAPMUnwrap) ]

that are indicators that it is wrapped. However, those symbol names are not published names so it would be somewhat of a hack to bother checking.

Copy link
Contributor

@astorm astorm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

@trentm trentm merged commit 32a95d5 into master Aug 16, 2021
@trentm trentm deleted the trentm/do-not-trace-http-client branch August 16, 2021 16:59
@trentm
Copy link
Member Author

trentm commented Aug 16, 2021

[email protected] published, v9.9.0 tagged

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
agent-nodejs Make available for APM Agents project planning.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants