disableSend env var also disables automatic traces and transactions creation

[angelos3lex]

I have an express nodejs server, and as I'm using webpack, I can't use the require("elastic-apm-node").start in the runtime code, due to the way webpack traverses the row of the imports.

So, I'm setting env var: ELASTIC_APM_DISABLE_SEND=true.
I'm starting the agent using node -r elastic-apm-node/start --unhandled-rejections=strict ./dist/app.js
The communication with apm server stops as expected, but the traces and transactions that were previously automatically generated are no longer generated and i loose log correlation.

Expected behavior

I expect the traces and transactions ids to be generated as well, as mentioned in the API docs.

Environment (please complete the following information)

• OS: Linux
• Node.js version: 10.13
• elastic-apm-node: ^3.18.0
  Just in case its helpful, I'm using winston, express-winston and @elastic/ecs-winston-format)

How are you starting the agent? (please tick one of the boxes)

• Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
• Requiring elastic-apm-node/start from within the source code
• Starting node with -r elastic-apm-node/start

Also, something weird that may has to do with the problem, is that to make it work, i start node using node with -r elastic-apm-node/start but also on the top of the file, I have: require("elastic-apm-node/start");. If i remove this line from the top of my entry file executable, the apm automatic traces/transactions etc isn't working even when i remove the disableSend env var, like it's never started.

[trentm]

@angelos3lex Thanks. A couple things:

1. The disableSend var that we added recently will probably need to change so its only impact is to not send data to APM server, because that's what Elastic's Python and Ruby APM agents do with their disable_send config var (per this spec discussion: add context_propagation_only config option, spec existing disable_send config option apm#461). Currently as implemented the Node.js APM agent is attempting to skip doing some processing when disableSend=true to save some CPU cycles.

2. However, the intent of the current implementation is that log correlation should still work, so there is something in your use case that I don't yet understand.

If you are able to provide a small repro script/repo with webpack build steps that would be immensely helpful as I don't have much experience with webpack.

i start node using node with -r elastic-apm-node/start but also on the top of the file, I have: require("elastic-apm-node/start");.

This sounds suspicious. Almost like the -r elastic-apm-node/start is not getting used, otherwise I would expect that require("elastic-apm-node/start"); in your code to result in a thrown Error from this code: https://github.com/elastic/apm-agent-nodejs/blob/master/lib/agent.js#L202

[angelos3lex]

Thanks for your reply. From what i understand, is that even if the disableSent is going to change, both in a future implementation and in current, the log correlation feature should work. So something is problematic on my side.
I will try to make a small repro repo asap. (It's true, the node -r elastic-apm-node/start is skipped, i removed it and I get same results)

[angelos3lex]

@trentm So, here is the link to the repo.
Steps to run it available in the readme. I personally run it with node v14.17.0 in a linux machine.
By default, the ELASTIC_APM_DISABLE_SEND is false, there is the -r elastic-apm-node/start in the start script and also the const apm = require("elastic-apm-node/start"); on top of the entry app.ts file.

If we hit http://localhost:3000/test as described in readme, we get two logs, and there is log correlation between them.

Things i noticed:

• Keeping everything as default but change .env var ELASTIC_APM_DISABLE_SEND to true disables log correlation.
• Keeping everything as default but remove const apm = require("elastic-apm-node/start"); from top of app.ts file, again disables log-correlation.
• Keeping everything as default but remove -r elastic-apm-node/start again disables log-correlation, like it never starts the agent.

[trentm]

@angelos3lex Thanks very much for the repo. This is just what I need. I've made some progress, but I don't have an answer yet.

[trentm]

Thanks so much for putting the repo together.

Okay, wow, there are a number of things going on here. Ultimately, the news isn't great: tracing of webpack-bundled modules will not work. What output you were getting is a combination of limited tracing and some misleading info.

The general advice for webpack + APM usage (not just for Elastic's APM, but for others as well) is to use the webpack-node-externals package to exclude everything under node_modules/... (or at the least the agent, the ecs-logging lib, and any packages you want traced) from the bundled "dist/app.js". This may or may not defeat the purpose of using webpack for you.

diff --git a/webpack.config.js b/webpack.config.js
index dddae8a..e741a32 100644
--- a/webpack.config.js
+++ b/webpack.config.js
@@ -1,5 +1,6 @@
 const path = require('path');
 const { CleanWebpackPlugin } = require('clean-webpack-plugin');
+const nodeExternals = require('webpack-node-externals');

 module.exports = {
     entry: path.join(__dirname, '/app.ts'),
@@ -22,8 +23,9 @@ module.exports = {
         new CleanWebpackPlugin()
     ],
     target: 'node',
+    externals: [nodeExternals()],
     node: {
         __dirname: true,
         __filename: false,

and then I was able get tracing and log correlation with or without ELASTIC_APM_DISABLE_SEND=true. My full diff to your repo is: https://gist.github.com/trentm/54a1bd3ced2be1346a4441cd080231fd

I hope to (after I am able to finish up some current work) get to improving our agent docs on this.

details

First, with both:

1. node -r elastic-apm-node/start ..., and
2. var apm = require('elastic-apm-node').start()
   two separate Agents are being created. The usual mechanism the agent uses to attempt to guarantee a singleton -- that require('elastic-apm-node') called multiple times resolves to the same file path and is only executed once -- is foiled when using webpack because (1) is the file "node_modules/elastic-apm-node/start.js", but (2) is the elastic-apm-node module bundled into the webpacked dist/app.js.

Having two Agents in play generally will break things because it necessarily makes changes to Node's global state and two of them will conflict, or have surprising results.

With your repo, unchanged, what is happening is (you can better see what is going on with ELASTIC_APM_LOG_LEVEL=trace npm run start | ecslog, get ecslog here):

• An agent, we will call it "Agent A", is started by node -r elastic-apm-node/start, which succesfully sets up for instrumenting subsequent require statements and instruments the node core "http" module soon after (when later code in the agent itself does require('http')).

  [2021-09-14T16:22:44.584Z] DEBUG (elastic-apm-node): adding hook to Node.js module loader
  [2021-09-14T16:22:44.618Z] DEBUG (elastic-apm-node): shimming http@12.22.6 module
  ...
  

• Then the "dist/app.js" loads the bundled "elastic-apm-node" for the var apm = require('elastic-apm-node').start() statement and starts a second agent, "Agent B". Agent B's hooking into require-statements somewhat works because of some interplay with Agent A that I didn't track down, because frankly all bets are off with two running Agents. This "somewhat works" is sufficient for Agent B to have instrumentation of the core "http" module. Note that neither of the Agents have instrumentation on the bundled "express" module.

• When the "POST /test" endpoint is hit there are two transactions created -- one by each agent -- because they both have instrumentation on the core "http" module. Both are reported to APM server. The log correlation picks up the trace.id and transaction.id values from one of those transactions (I believe from Agent B).

Things i noticed:

* Keeping everything as default but change .env var `ELASTIC_APM_DISABLE_SEND` to `true` disables log correlation.

I believe what is happening here is that ELASTIC_APM_DISABLE_SEND=true means there are no HTTP requests from Agent A or Agent B to the APM server. The handling of these internal HTTP requests was a crutch (due to a bug in internal async context tracking) that would result in the log correlation code (in the @elastic/ecs-winston-format package) being able to get the current transaction/trace identifiers. This is somewhat of a guess, however. I didn't not track that down because, as I said above, with two Agents in play, bets are off.

* Keeping everything as default but remove `const apm = require("elastic-apm-node/start");` from top of `app.ts` file, again disables log-correlation.

In this case "Agent A", as above, successfully can instrument unbundled modules, like the core "http" module. A transaction is created and sent to APM server. However, the bundled @elastic/ecs-winston-format cannot get a handle on the APM agent because its require('elastic-apm-node') attempt is changed by webpack to __webpack_require__(<a numeric code for elastic-apm-node>) which gets the bundled "elastic-apm-node" package, for which an Agent is not started.

* Keeping everything as default but remove `-r elastic-apm-node/start` again disables log-correlation, like it never starts the agent.

In this case "Agent B" is started, but its hooks into require either do not work at all, or work but by the time it runs, the "http" core module has already been imported. The result is that the running Agent B does not have hooks into the "http" core module so no tracing is done for http requests and hence there is no current trace/transaction for log correlation.

I haven't dug into the "either ..., or" issue because, ultimately getting tracing to work properly requires not bundling modules to be traced (as mentioned above), or someone getting deeply involved into webpack internals to see if it is possible to hook into __webpack_require__ or similar (as is mentioned briefly here).

[trentm]

#1967 Is the issue in which I'm going attempt to improve docs (and perhaps agent internals tohelp somewhat). The tl;dr is still going to be "use 'externals' in webpack.config.js to unbundle deps that one needs traced".

[trentm]

@angelos3lex I'm closing this issue now. Please feel free to re-open if you still have questions or if I've missed something. Hopefully using webpack "externals" config is sufficient for your case.