apm-agent-nodejs icon indicating copy to clipboard operation
apm-agent-nodejs copied to clipboard
verified publisher icon elastic

`ignoreUrls` and `transactionIgnoreUrls` doesn't work at all!?!

Open khteh opened this issue 2 years ago • 5 comments

Describe the bug

I have the following ignoreUrls configured:

    ignoreUrls: [
      /^\/health\//i,
      /^\/[._]+next\//i,
      /^\/robots.txt/
    ],
    transactionIgnoreUrls: [
      '/health/*',
      '/.next/*',
      '/_next/*',
      '/robots.txt'
    ],

But the _next/* still appears in APM Transactions in Kibana. To Reproduce

Steps to reproduce the behavior:

  1. Use this config '...'
  2. Then call '....'
  3. Then do '....'
  4. See error

Expected behavior

Environment (please complete the following information)

  • OS: [e.g. Linux]
  • Node.js version:
  • APM Server version:
  • Agent version:

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

  • [x] 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

Agent config options:

Click to expand 
replace this line with your agent config options

package.json dependencies:

Click to expand 
replace this line with your dependencies section from package.json

khteh avatar Oct 13 '23 08:10 khteh

Hi @khteh,

Here is an "http-ignore-urls.example.js" script showing that those two "ignore" settings are working for me:

require('elastic-apm-node').start({
  serviceName: 'http-ignore-urls',
  usePathAsTransactionName: true, // This example doesn't use a framework with explicit routes, so use this for testing.
  disableSend: true, // Turn off actually sending data, while we debug locally.
  logLevel: 'debug',
  // I am just testing one at a time. Shouldn't need both "ignore" options.
  ignoreUrls: [/^\/health\//i, /^\/[._]+next\//i, /^\/robots.txt/],
  // transactionIgnoreUrls: ['/health/*', '/.next/*', '/_next/*', '/robots.txt'],
});

const http = require('http');
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 () {
    const resBody = 'pong';
    res.writeHead(200, {
      'content-type': 'text/plain',
      'content-length': Buffer.byteLength(resBody),
    });
    res.end(resBody);
  });
});
server.listen(3000);

When I run that and call it with:

% curl -i http://localhost:3000/_next/foo
HTTP/1.1 200 OK
content-type: text/plain
content-length: 4
Date: Fri, 13 Oct 2023 16:21:04 GMT
Connection: keep-alive
Keep-Alive: timeout=5

pong

I see this "ignoring request to ..." message in the APM agent log output:

% node http-ignore-urls.example.js
...
incoming request: GET /_next/foo { host: 'localhost:3000', 'user-agent': 'curl/8.1.2', accept: '*/*' }
{"log.level":"debug","@timestamp":"2023-10-13T16:21:04.685Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"ignoring request to /_next/foo"}

And when I call with some not-ignored path, e.g. curl -i http://localhost:3000/asdf, I see:

...
incoming request: GET /asdf { host: 'localhost:3000', 'user-agent': 'curl/8.1.2', accept: '*/*' }
{"log.level":"debug","@timestamp":"2023-10-13T16:22:22.285Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"9ce67082b7dc579e\",\"trace\":\"1763d5529b879cc2176bffdb663e8213\",\"name\":\"unnamed\",\"type\":\"custom\"}"}
...
{"log.level":"debug","@timestamp":"2023-10-13T16:22:22.286Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: GET /asdf {\"trans\":\"9ce67082b7dc579e\",\"trace\":\"1763d5529b879cc2176bffdb663e8213\"}"}
...

Are you able to turn on logLevel: 'debug' and post some of the debug log output from the APM agent so we can dig a little deeper?

issue with the "/robots.txt" config value

I did notice a related bug in the APM agent when the incoming request has query parameters. With transactionIgnoreUrls: [..., '/robots.txt'], config setting, a GET /robots.txt request will be ignored, but a GET /robots.txt?foo will not. I'll open a separate issue for that on the APM agent.

trentm avatar Oct 13 '23 16:10 trentm

I'll open a separate issue for that on the APM agent.

https://github.com/elastic/apm-agent-nodejs/issues/3667 for that. However, I don't believe that is the issue you are hitting here.

trentm avatar Oct 13 '23 16:10 trentm 

[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.129Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"8000d9328b75e4cd\",\"trace\":\"d864a67fce3f346af6aab02413004417\",\"name\":\"unnamed\",\"type\":\"custom\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.129Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext(Transaction(8000d9328b75e4cd, '/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/1af25aff-d8d7-4b4d-9866-d6e0a67acd08.json')) )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 8000d9328b75e4cd>)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.130Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext() )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/1af25aff-d8d7-4b4d-9866-d6e0a67acd08.json)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.130Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"8000d9328b75e4cd\",\"trace\":\"d864a67fce3f346af6aab02413004417\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.130Z","log":{"logger":"elastic-apm-node"},"trans":"8000d9328b75e4cd","name":"/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/1af25aff-d8d7-4b4d-9866-d6e0a67acd08.json","trace":"d864a67fce3f346af6aab02413004417","type":"custom","result":"success","duration":0.67,"ecs":{"version":"1.6.0"},"message":"ended transaction"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.222Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"65ff6d0de268b2f1\",\"trace\":\"2cde4ca900620273bea14052e6842e4f\",\"name\":\"unnamed\",\"type\":\"custom\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.222Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext(Transaction(65ff6d0de268b2f1, '/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/03f833fa-da9d-4da1-88ea-a58c030d1f85.json')) )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans 65ff6d0de268b2f1>)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.222Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext() )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/03f833fa-da9d-4da1-88ea-a58c030d1f85.json)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.222Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"65ff6d0de268b2f1\",\"trace\":\"2cde4ca900620273bea14052e6842e4f\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.222Z","log":{"logger":"elastic-apm-node"},"trans":"65ff6d0de268b2f1","name":"/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/03f833fa-da9d-4da1-88ea-a58c030d1f85.json","trace":"2cde4ca900620273bea14052e6842e4f","type":"custom","result":"success","duration":0.42,"ecs":{"version":"1.6.0"},"message":"ended transaction"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.228Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"a89b6a91fee12580\",\"trace\":\"04cb284acb90f7604834afcbb2e19f21\",\"name\":\"unnamed\",\"type\":\"custom\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.228Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext(Transaction(a89b6a91fee12580, '/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/012c53ca-22ff-4225-a041-ac1818bd6b47.json')) )","ecs":{"version":"1.6.0"},"message":"supersedeWithTransRunContext(<Trans a89b6a91fee12580>)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.229Z","log":{"logger":"elastic-apm-node"},"ctxmgr":"AsyncLocalStorageRunContextManager( RunContext() )","ecs":{"version":"1.6.0"},"message":"addEndedTransaction(/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/012c53ca-22ff-4225-a041-ac1818bd6b47.json)"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.229Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"sending transaction {\"trans\":\"a89b6a91fee12580\",\"trace\":\"04cb284acb90f7604834afcbb2e19f21\"}"} 
[myapp-1 myapp] {"log.level":"debug","@timestamp":"2023-10-14T03:20:18.229Z","log":{"logger":"elastic-apm-node"},"trans":"a89b6a91fee12580","name":"/_next/data/1JHLr2hkCeT3m7UqPickI/mypage/012c53ca-22ff-4225-a041-ac1818bd6b47.json","trace":"04cb284acb90f7604834afcbb2e19f21","type":"custom","result":"success","duration":0.714,"ecs":{"version":"1.6.0"},"message":"ended transaction"}

khteh avatar Oct 14 '23 03:10 khteh

Hi @khteh,

Did you edit some lines out of the middle of those log lines? I would have expected to see a log line with "setting transaction result" in the message, and one with "setting default transaction name" in the message, and one with "intercepted request event call to http.Server.prototype.emit for" in the message.

One thing that would really help, and save us going back and forth with questions, would be: a complete debug log from application startup, until a few requests have been handled.

The best thing that would help is if you could show a complete small reproduction case that I could try on my end.

What versions of your dependencies (e.g. "next") are you using?

How are you starting the Next.js server? next start? next dev?

Is it possible that HTTP/2 (as opposed to HTTP/1.1) is involved here?

Note that we do have experimental support for instrumenting Next.js. It is described here: https://www.elastic.co/guide/en/apm/agent/nodejs/master/nextjs.html However, I don't think details in that document are related to the issue you are currently seeing.

trentm avatar Oct 16 '23 23:10 trentm

I don't find any of the log patterns you suggested:

$ k logs -f buyerportal-0 | grep "setting transaction result"
Defaulted container "buyerportal" out of: buyerportal, fluentd
^C
$ k logs -f buyerportal-0 | grep "setting default transaction name"
Defaulted container "buyerportal" out of: buyerportal, fluentd
^C
$ k logs -f buyerportal-0 | grep "intercepted request event call to http.Server.prototype.emit for"
Defaulted container "buyerportal" out of: buyerportal, fluentd

What versions of your dependencies (e.g. "next") are you using?

"next": "13.5.4",

How are you starting the Next.js server? next start? next dev? SPDY -> Express -> Next.JS

Is it possible that HTTP/2 (as opposed to HTTP/1.1) is involved here? YES.

khteh avatar Oct 17 '23 05:10 khteh