Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Express with Webpack not sending Transactions #1962

Closed
1 of 3 tasks
baruchiro opened this issue Feb 1, 2021 · 14 comments
Closed
1 of 3 tasks

Express with Webpack not sending Transactions #1962

baruchiro opened this issue Feb 1, 2021 · 14 comments
Labels
agent-nodejs Make available for APM Agents project planning.

Comments

@baruchiro
Copy link

Describe the bug

I have an express service that bundled with Webpack and runs on Docker (it's mean that in the Dockerfile you just need CMD ["node", "--enable-source-maps", "main.js"]

To Reproduce

Steps to reproduce the behavior:

  1. Create a simple Express service.
  2. Add import apm from 'elastic-apm-node/start' at the top on the file.
  3. Create a webpack.config.js file:
const { CleanWebpackPlugin } = require('clean-webpack-plugin')

module.exports = {

    target: 'node',
    mode: 'production',
    devtool: 'source-map',
    module: {
        rules: [
            {
                test: /\.js$/,
                include: __dirname + '/src',
                use: 'babel-loader'
            }
        ]
    },
    plugins: [
        new CleanWebpackPlugin()
    ]
}
  1. Use these variables:
ELASTIC_APM_SERVER_URL=http://apm-server:8200
ELASTIC_APM_VERIFY_SERVER_CERT=false
ELASTIC_APM_LOG_LEVEL=trace
ELASTIC_APM_SERVICE_NAME=service-name

Expected behavior

When I'm running in debug mode, without webpack, by babel-node --inspect=33180 src/index.js, I'm getting the transactions as expected.

Here is the configuration output from Debug mode:

agent configured correctly {
  pid: 21432,
  ppid: 17216,
  arch: 'x64',
  platform: 'win32',
  node: 'v12.18.2',
  agent: '3.10.0',
  ancestors: [
    'absolutePath\\service-name\\node_modules\\elastic-apm-node\\index.js',
    'absolutePath\\service-name\\node_modules\\elastic-apm-node\\start.js',
    'absolutePath\\service-name\\src\\index.js',
    [length]: 3
  ],
  startTrace: [
    'at Agent.start (absolutePath\\service-name\\node_modules\\elastic-apm-node\\lib\\agent.js:154:11)',
    'at Object.<anonymous> (absolutePath\\service-name\\node_modules\\elastic-apm-node\\start.js:3:32)',
    'at Module._compile (internal/modules/cjs/loader.js:1138:30)',
    'at Module._compile (absolutePath\\service-name\\node_modules\\pirates\\lib\\index.js:99:24)',
    'at Module._extensions..js (internal/modules/cjs/loader.js:1158:10)',
    'at Object.newLoader [as .js] (absolutePath\\service-name\\node_modules\\pirates\\lib\\index.js:104:7)',
    'at Module.load (internal/modules/cjs/loader.js:986:32)',
    'at Function.Module._load (internal/modules/cjs/loader.js:879:14)',
    'at Module.require (internal/modules/cjs/loader.js:1026:19)',
    'at require (internal/modules/cjs/helpers.js:72:18)',
    [length]: 10
  ],
  main: undefined,
  dependencies: undefined,
  conf: {
    ignoreUrlStr: [ [length]: 0 ],
    ignoreUrlRegExp: [ [length]: 0 ],
    ignoreUserAgentStr: [ [length]: 0 ],
    ignoreUserAgentRegExp: [ [length]: 0 ],
    transactionIgnoreUrlRegExp: [ [length]: 0 ],
    sanitizeFieldNamesRegExp: [
      /^password$/i { [lastIndex]: 0 },
      /^passwd$/i { [lastIndex]: 0 },
      /^pwd$/i { [lastIndex]: 0 },
      /^secret$/i { [lastIndex]: 0 },
      /^.*key$/i { [lastIndex]: 0 },
      /^.*token.*$/i { [lastIndex]: 0 },
      /^.*session.*$/i { [lastIndex]: 0 },
      /^.*credit.*$/i { [lastIndex]: 0 },
      /^.*card.*$/i { [lastIndex]: 0 },
      /^authorization$/i { [lastIndex]: 0 },
      /^set\x2dcookie$/i { [lastIndex]: 0 },
      /^pw$/i { [lastIndex]: 0 },
      /^pass$/i { [lastIndex]: 0 },
      /^connect\.sid$/i { [lastIndex]: 0 },
      [length]: 14
    ],
    abortedErrorThreshold: 25,
    active: true,
    apiRequestSize: 786432,
    apiRequestTime: 10,
    asyncHooks: true,
    breakdownMetrics: true,
    captureBody: 'off',
    captureErrorLogStackTraces: 'messages',
    captureExceptions: true,
    captureHeaders: true,
    captureSpanStackTraces: true,
    centralConfig: true,
    disableInstrumentations: [ [length]: 0 ],
    environment: 'development',
    errorMessageMaxLength: 2048,
    errorOnAbortedRequests: false,
    filterHttpHeaders: true,
    instrument: true,
    instrumentIncomingHTTPRequests: true,
    logLevel: 'trace',
    logUncaughtExceptions: false,
    metricsInterval: 30,
    metricsLimit: 1000,
    sanitizeFieldNames: [
      'password',   'passwd',
      'pwd',        'secret',
      '*key',       '*token*',
      '*session*',  '*credit*',
      '*card*',     'authorization',
      'set-cookie', 'pw',
      'pass',       'connect.sid',
      [length]: 14
    ],
    serverTimeout: 30,
    sourceLinesErrorAppFrames: 5,
    sourceLinesErrorLibraryFrames: 5,
    sourceLinesSpanAppFrames: 0,
    sourceLinesSpanLibraryFrames: 0,
    stackTraceLimit: 50,
    transactionIgnoreUrls: [ [length]: 0 ],
    transactionMaxSpans: 500,
    transactionSampleRate: 1,
    useElasticTraceparentHeader: true,
    usePathAsTransactionName: false,
    verifyServerCert: false,
    serverUrl: 'http://apm-server:8200',
    serviceName: 'service-name',
    serviceVersion: '1.0.0',
    serverHost: 'apm-server:8200',
    serverPort: 8200
  }
}
 node_modules/console-log-level/index.js
adding hook to Node.js module loader
 node_modules/console-log-level/index.js
shimming http@12.18.2 module
 node_modules/console-log-level/index.js
shimming http.Server.prototype.emit function
 node_modules/console-log-level/index.js
shimming http.ServerResponse.prototype.writeHead function
 node_modules/console-log-level/index.js
shimming http.request function
 node_modules/console-log-level/index.js
shimming http.get function
 node_modules/console-log-level/index.js
shimming https@12.18.2 module
 node_modules/console-log-level/index.js
shimming https.Server.prototype.emit function
 node_modules/console-log-level/index.js
shimming https.request function
 node_modules/console-log-level/index.js
shimming https.get function
 node_modules/console-log-level/index.js
shimming elasticsearch@15.5.0 module
 node_modules/console-log-level/index.js
shimming elasticsearch.Transport.prototype.request
 node_modules/console-log-level/index.js
shimming finalhandler@1.1.2 module
 node_modules/console-log-level/index.js
shimming express@4.17.1 module
 node_modules/console-log-level/index.js
shimming express.Router.use function
 node_modules/console-log-level/index.js
shimming express.static function
 node_modules/console-log-level/index.js
copying property mime from express.static
 node_modules/console-log-level/index.js
shimming mongodb@3.6.0 module
 node_modules/console-log-level/index.js
shimming express.Router.Layer.handle function: query
 node_modules/console-log-level/index.js
shimming express.Router.Layer.handle function: expressInit
 node_modules/console-log-level/index.js
shimming express.Router.Layer.handle function: compression
 node_modules/console-log-level/index.js
shimming express.Router.Layer.handle function: corsMiddleware
 node_modules/console-log-level/index.js
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
shimming express.Router.Layer.handle function: bound dispatch
 node_modules/console-log-level/index.js

Actual behavior

But in production, I can see the service, I even capturing errors manually, but I can't see the transactions.

Here is the config output from the production (webpack) run:

agent configured correctly {
�
,
  ppid: 0,
  arch: 'x64',
  platform: 'linux',
  node: 'v12.19.1',
  agent: '3.10.0',
  ancestors: [ [length]: 0 ],
  startTrace: [
    'at v.start (/usr/src/app/main.js:200:3475)',
    'at Object.<anonymous> (/usr/src/app/main.js:200:67)',
    'at n (/usr/src/app/main.js:1:110)',
    'at Module.<anonymous> (/usr/src/app/main.js:384:219812)',
    'at n (/usr/src/app/main.js:1:110)',
    'at /usr/src/app/main.js:1:902',
    'at Object.<anonymous> (/usr/src/app/main.js:1:913)',
    'at Module._compile (internal/modules/cjs/loader.js:1015:30)',
    'at Object.Module._extensions..js (internal/modules/cjs/loader.js:1035:10)',
    'at Module.load (internal/modules/cjs/loader.js:879:32)',
    [length]: 10
  ],
  main: undefined,
  dependencies: undefined,
�
{
    ignoreUrlStr: [ [length]: 0 ],
    ignoreUrlRegExp: [ [length]: 0 ],
    ignoreUserAgentStr: [ [length]: 0 ],
    ignoreUserAgentRegExp: [ [length]: 0 ],
    transactionIgnoreUrlRegExp: [ [length]: 0 ],
    sanitizeFieldNamesRegExp: [
      /^password$/i { [lastIndex]: 0 },
      /^passwd$/i { [lastIndex]: 0 },
      /^pwd$/i { [lastIndex]: 0 },
      /^secret$/i { [lastIndex]: 0 },
      /^.*key$/i { [lastIndex]: 0 },
      /^.*token.*$/i { [lastIndex]: 0 },
      /^.*session.*$/i { [lastIndex]: 0 },
      /^.*credit.*$/i { [lastIndex]: 0 },
      /^.*card.*$/i { [lastIndex]: 0 },
      /^authorization$/i { [lastIndex]: 0 },
      /^set\x2dcookie$/i { [lastIndex]: 0 },
      /^pw$/i { [lastIndex]: 0 },
      /^pass$/i { [lastIndex]: 0 },
      /^connect\.sid$/i { [lastIndex]: 0 },
      [length]: 14
    ],
    abortedErrorThreshold: 25,
    active: true,
    apiRequestSize: 786432,
    apiRequestTime: 10,
    asyncHooks: true,
    breakdownMetrics: true,
    captureBody: 'off',
    captureErrorLogStackTraces: 'messages',
    captureExceptions: true,
    captureHeaders: true,
    captureSpanStackTraces: true,
    centralConfig: true,
    disableInstrumentations: [ [length]: 0 ],
    environment: 'production',
    errorMessageMaxLength: 2048,
    errorOnAbortedRequests: false,
    filterHttpHeaders: true,
    instrument: true,
    instrumentIncomingHTTPRequests: true,
    logLevel: 'trace',
    logUncaughtExceptions: false,
    metricsInterval: 30,
    metricsLimit: 1000,
    sanitizeFieldNames: [
      'password',   'passwd',
      'pwd',        'secret',
      '*key',       '*token*',
      '*session*',  '*credit*',
      '*card*',     'authorization',
      'set-cookie', 'pw',
      'pass',       'connect.sid',
      [length]: 14
    ],
    serverTimeout: 30,
    sourceLinesErrorAppFrames: 5,
    sourceLinesErrorLibraryFrames: 5,
    sourceLinesSpanAppFrames: 0,
    sourceLinesSpanLibraryFrames: 0,
    stackTraceLimit: 50,
    transactionIgnoreUrls: [ [length]: 0 ],
    transactionMaxSpans: 500,
    transactionSampleRate: 1,
    useElasticTraceparentHeader: true,
    usePathAsTransactionName: false,
    verifyServerCert: false,
    serverUrl: 'http://apm-server:8200',
    serviceName: 'service-name-dev-env',
    serverHost: 'apm-server:8200',
    serverPort: 8200
  }
}
adding hook to Node.js module loader
shimming https@12.19.1 module
shimming https.Server.prototype.emit function
shimming https.request function
shimming https.get function

Please note there are no ancestors, and there are fewer shimming. Also, note I named the "production" (webpack) service with a different name ('service-name-dev-env) to identify it.

Environment (please complete the following information)

You can see the config output. It is better.

APM Server version:

{
    "build_date": "2019-03-06T14:11:42Z",
    "build_sha": "daad5449d758e7bf101f6482778a2b15f646a67f",
    "version": "6.6.2"
}

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

Additional context

  • package.json dependencies:

    Click to expand
    "dependencies": {
        "axios": "^0.18.1",
        "compression": "^1.7.4",
        "cors": "^2.8.5",
        "elastic-apm-node": "^3.10.0",
        "elasticsearch": "^15.4.1",
        "express": "^4.17.1",
        "http-status-codes": "^1.4.0",
        "mongodb": "^3.5.2"
    },
    "devDependencies": {
        "@babel/core": "^7.10.4",
        "@babel/preset-env": "^7.10.4",
        "babel-loader": "^8.1.0",
        "clean-webpack-plugin": "^3.0.0",
        "webpack": "^4.43.0",
        "webpack-cli": "^3.3.12"
    },
    "optionalDependencies": {
        "@babel/cli": "^7.10.4",
        "@babel/node": "^7.10.4",
        "@team17/eslint-config": "^2.1.0",
        "babel-eslint": "^10.1.0",
        "babel-jest": "^26.3.0",
        "eslint": "^6.8.0",
        "eslint-friendly-formatter": "^4.0.1",
        "eslint-plugin-babel": "^5.3.1",
        "eslint-plugin-jest": "^23.20.0",
        "husky": "^4.2.5",
        "jest": "^26.4.2"
    }
    
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Feb 1, 2021
@baruchiro
Copy link
Author

Maybe to workaround, I can use the "Starting node with -r elastic-apm-node/start" option?

I don't know this option.

@astorm
Copy link
Contributor

astorm commented Feb 1, 2021

Nice to meet you @baruchiro, and thank you for the detailed bug report.

Here's the usual problem we see with webpack (or other compiler/transpiler/bundlers). Although you've add import apm from 'elastic-apm-node/start' to the top of your main entry point, webpack's final compiled source changes the order that modules are loaded in -- by default I believe modules are lazy loaded -- i.e. webpack won't load the elastic-apm-node module until you actually use (not just define) the apm variable in your program. This conflicts with the Agent's requirement that it be the first thing loaded. If the agent isn't the first thing loaded, it doesn't have a chance to instrument express or the http/https modules. Without those modules instrumented the agent can't create transactions.

Using the node -r elastic-apm-node/start ... entry-point.js option can often solve this problem. The -r (or --require option) tells node to load modules before it runs your program. This ensure that no matter what webpack is doing, that the agent is the first thing that's loaded.

So

Maybe to workaround, I can use the "Starting node with -r elastic-apm-node/start" option?

Yes, step one will be giving that a try :) Change how you're invoking node in your production environment to include the -r elastic-apm-node/start option and and let us know if that gets your transactions reporting.

@baruchiro
Copy link
Author

Hi, nice to meet you too!

I will try it, although it is the opposite way from webpack. Think about that, to use -r I need to install the dependencies tree for elastic-apm-node, so then why to bundle the service at all?

But I will try and update you, than we will think on another solution.

@astorm
Copy link
Contributor

astorm commented Feb 1, 2021

Let know how it goes @baruchiro! Also, if you have a moment: What benefit does your team get from bundling a Node.js server side application? Is there something specific you get from doing this, or are you just applying a best practice from your front end development workflows to the back end?

@baruchiro
Copy link
Author

Off-topic- why do we use Webpack for the backend?

I thought to write an article about that.

Anyway, we have two use-cases. For our discussion, we are talking about a backend service with Express. We are running that service in a Docker, and we have a lot of services (micro-services).

To reduce the Docker Image size, we are using Webpack to tree-shaking the dependencies and so on, so that we getting a minimal Docker Image:

# nodejs binaries
FROM node:12-alpine as binaries

# builder image
FROM node:12 as builder

WORKDIR /usr/src/app
COPY . .

RUN npm install
RUN npm run build

# release image
FROM alpine

COPY --from=binaries /usr/local/bin/node /usr/local/bin/
COPY --from=binaries /usr/lib/ /usr/lib/

WORKDIR /usr/src/app
COPY --from=builder /usr/src/app/dist .

CMD ["node", "--enable-source-maps", "main.js"]

@trentm
Copy link
Member

trentm commented Feb 2, 2021

@baruchiro Interesting. Thanks for telling your use case. Only if you know off hand, I'm curious how big of a difference that can make in the Docker size. (I'm guessing you would not know off hand, however, if you've been using webpack for a while.)

@baruchiro
Copy link
Author

@trentm Mmmm you're right, I can't give you off-hand (I can checkout an old version, you know, just ask me).

Anyway, I added the package to the docker:

RUN npm install --prefix /usr/lib/ elastic-apm-node
....
CMD ["node", "--enable-source-maps", "-r", "/usr/lib/node_modules/elastic-apm-node/start", "main.js"]

And it is working!


Now I have some points:

  • I didn't know about the option to -r elastic-apm-node/start, although if you think about that, it is a NodeJS option, but I think it will be good to document it somewhere.
  • It is working now by instrumenting the code. But what if we want to use custom-span, for example, how can I get the apm reference?
    As I said, it is more related to NodeJS itself. But I need to know how can I use apm, when it loaded by node -r, and when it not (in development).

@trentm
Copy link
Member

trentm commented Feb 5, 2021

will be good to document it somewhere

Sounds like the equivalent potential issue as #608 (where TypeScript fully removes the import of "elastic-apm-node" if the retval isn't actually used directly). I'm not sure, it might also be an ordering of imports thing.

Back then a note about using -r elastic-apm-node/start was put in https://www.elastic.co/guide/en/apm/agent/nodejs/current/agent-api.html#apm-start but I agree that is too hard to find and notice. (Also in the bug issue template, which is a little late. :) I think we should get a reference of this at https://www.elastic.co/guide/en/apm/agent/nodejs/current/starting-the-agent.html and/or a separate page covering potential usage issues with bundlers and transpilers.

But what if we want to use custom-span, for example, how can I get the apm reference?

You should be able to also re-import the module in JS code to get a handle on the agent:

const apm = require('elastic-apm-node')

// ...
const span = apm.startSpan(...)

the return value from that require is a singleton reference to the APM Agent.

@trentm
Copy link
Member

trentm commented Feb 5, 2021

I've opened #1967 to add better docs for this.

@baruchiro
Copy link
Author

baruchiro commented Feb 7, 2021

You should be able to also re-import the module in JS code to get a handle on the agent:

const apm = require('elastic-apm-node')

// ...
const span = apm.startSpan(...)

the return value from that require is a singleton reference to the APM Agent.

Mmmm... Sounds logical, but I think it didn't work. Because remember, we are talking about running a bundle, so I'm not sure it still a singleton. I mean, when you require a module multiple times, it actually requiring it once, right? But here I'm requiring it outside the bundle, but in the bundle, I'm not requiring it at all, because of the tree-shaking, it runs the code itself, duplicated.

When I'm trying to require it by -r and import it by import apm from 'elastic-apm-node to use apm.startSpan, it printing this:

intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.get { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

(It seems like someone requesting the service. Or maybe it a health check from one of the connections inside the service)

After sending request which should use the spanned code, I can't see the span in Kibana.

I added this code:

const span = apm.startSpan('validating log')
console.log('start span', span)
try {
    // ... Original Code
} finally {
    console.log('finally span', span)
    span?.end()
}

and this is the log:

no active transaction found - cannot build new span
intercepted call to http.request { id: null }
intercepted request event call to http.Server.prototype.emit for /validate
start trace {
  trans: '352f88f5358ab1a5',
  parent: undefined,
  trace: 'a5cfb5185e81d6be1ba86c01f4b3a0ba',
  name: 'unnamed',
  type: null,
  subtype: null,
  action: null
}
no active transaction found - cannot build new span
intercepted call to http.request { id: null }
no active transaction found - cannot build new span
start span null
finally span null
setting transaction result {
  trans: '352f88f5358ab1a5',
  parent: undefined,
  trace: 'a5cfb5185e81d6be1ba86c01f4b3a0ba',
  result: 'HTTP 2xx'
}
setting default transaction name: POST /validate {
  trans: '352f88f5358ab1a5',
  parent: undefined,
  trace: 'a5cfb5185e81d6be1ba86c01f4b3a0ba'
}
sending transaction {
  trans: '352f88f5358ab1a5',
  trace: 'a5cfb5185e81d6be1ba86c01f4b3a0ba'
}
ended transaction {
  trans: '352f88f5358ab1a5',
  parent: undefined,
  trace: 'a5cfb5185e81d6be1ba86c01f4b3a0ba',
  type: 'request',
  result: 'HTTP 2xx',
  name: 'POST /validate'
}
no active transaction found - cannot build new span
intercepted call to http.request { id: null }

Note to the start span null and finally span null in the middle of the log.

@Shadist
Copy link

Shadist commented Feb 10, 2021

(It seems like someone requesting the service. Or maybe it a health check from one of the connections inside the service)

Same problem for us, we use angular universal (babel, typescript included).

@trentm
Copy link
Member

trentm commented Sep 14, 2021

Mmmm... Sounds logical, but I think it didn't work.

I think you are right. Sorry, I know this issue has languished. I have some more notes here in case it helps for now: #2318 (comment)

@gtorre
Copy link

gtorre commented Dec 10, 2021

@trentm huge thank you for your help on this. We had a similar issue to @baruchiro. Loading the agent first in the Dockerfile did the trick! I'm hopeful #1967 is merged soon 🤞

@trentm
Copy link
Member

trentm commented Jul 29, 2022

#1967 is in now, which will hopefully help more. PR: #2837

https://www.elastic.co/guide/en/apm/agent/nodejs/master/starting-the-agent.html#start-bundlers tries to cover issues with bundlers, such as Webpack. Basically to use the agent requires that it be excluded from the bundle. The docs cover options for doing that for Webpack and esbuild. (Instructions for other bundlers, if you have experience using it and the APM agent, would be welcome.) I realize this is just a workaround.

I think future work that would be good would be to see if the APM agent can tell if it has been bundled, and then complain with a warning and then deactivate. I haven't looked to far into if that is feasible.

We might in the future look into if it would be possible to improve on the story with bundlers, possibly including:

  • a webpack plugin that would make it more obvious/easy to make the APM agent "external"
  • even perhaps APM agent work and a webpack plugin that could get the agent and its instrumentation to work in a bundle.

I'm closing this issue. Please re-open and let me know if, in my haste, I missed points that should still be answered here. Thanks very much for the bug reports.

@trentm trentm closed this as completed Jul 29, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-nodejs Make available for APM Agents project planning.
Projects
None yet
Development

No branches or pull requests

5 participants