APM and Koa unknown route

hsabillon · August 12, 2021, 3:48pm

I'm currently using APM (elastic-apm-node 3.18.0), koa, and koa-router on one service. The problem is that even if I give a transaction name with transaction.name, APM tries to get the name from the koa-router. It's there any way to avoid this behavior?

alanstorm · August 12, 2021, 4:13pm

Thanks for reporting @hsabillon -- that doesn't sound like the intended behavior.

Do you have some sample code that demonstrates the behavior? With that in hand we can usually figure out what's going on and advise you on a work-around and/or get a fix into the agent proper.

hsabillon · August 12, 2021, 5:08pm

@alanstorm it will be difficult to share the code cause rules but is there any way on APM to ignore koa/koa-router?

Tried with ELASTIC_APM_DISABLE_INSTRUMENTARIONS=koa,koa-router but the result is the same.

Also wanted to know if transaction.name is equivalent to transaction.setTransactionName() to naming a transaction

alanstorm · August 12, 2021, 11:28pm

Thank you @hsabillon -- we understand you can't share your actual production code with us. However, if you can share a small program that reproduces the behavior you've described it would go a long way towards us helping you. It's not clear how you're using transaction.name, or what exactly you mean when you say "get the name from the koa-router". Without knowing what you're seeing and doing it's hard/impossible to advise you.

For example -- when I use the following sample program

var apm = require('elastic-apm-node').start({/* ... */})

var Koa = require('koa');
var Router = require('koa-router');

var app = new Koa();
var router = new Router();

router.get('/goodbye', (ctx, next) => {
  // both setTransactionName and apm.currentTransaction.name 
  // rename the transaction succesfully
  // apm.setTransactionName('my new name')
  apm.currentTransaction.name = 'second new name'
  ctx.body = 'goodbye world'
});

app
  .use(router.routes())
  .use(router.allowedMethods());
app.listen(3000);

Both apm.setTransactionName and apm.currentTransaction.name = 'second new name' allow me to rename the transaction successfully.

If you can come up with a similar program the demonstrates the issue you're seeing, we can zero in on the problem and provide an explanation for what's going on, or get an issue open if this is a bug/unintended behavior.

To answer your specific questions

Tried with ELASTIC_APM_DISABLE_INSTRUMENTARIONS=koa,koa-router but the result is the same.

It looks like you have a typo in your env variable name. The correct name is ELASTIC_APM_DISABLE_INSTRUMENTATIONS

Also wanted to know if transaction.name is equivalent to transaction.setTransactionName() to naming a transaction

First -- when you say transaction.setTransactionName() I presume you mean apm.setTransactionName. There is no setTransactionName on the transaction object.

Second -- the short version is name and setTransactionName do the same thing. The long version is the setTransactionName method actually uses the dynamic property transaction.name to do its thing. The setTransactionName method starts here, and ends up executing this line.

This name property is actually a dynamic property, whose setter is defined here.

Hopefully there's enough here to either guide you to a solution or get us that reproduction we'll need to help you further.

hsabillon · August 13, 2021, 4:17pm

Thanks @alanstorm for all the information provided!

Yes, I've got a typo but only here on my response, on the actual code env variable is fine.

Think I have an actual code that reproduce the behavior

const apm = require('elastic-apm-node').start({
    serverUrl: 'http://some-apm-server',
    active: true,
    instrument: false,
    logLevel: 'trace',
});

const Koa = require('koa');
const Router = require('koa-router');

const app = new Koa();
const router = new Router();

router.get('/', (ctx, next) => {
    apm.setTransactionName('custom name');
    
    ctx.body = 'hello world';
});

app
    .use(router.routes())
    .use(router.allowedMethods());

app.listen(3000);

The resulting logs for that code

{"log.level":"debug","@timestamp":"2021-08-13T16:10:12.805Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"start trace {\"trans\":\"eb8b3b48dc363cb2\",\"trace\":\"e5d0c9c95ba516ca673603fecc1415f8\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}"}
{"log.level":"debug","@timestamp":"2021-08-13T16:10:12.807Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction name {\"trans\":\"eb8b3b48dc363cb2\",\"trace\":\"e5d0c9c95ba516ca673603fecc1415f8\",\"name\":\"custom name\"}"}
{"log.level":"debug","@timestamp":"2021-08-13T16:10:12.809Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting transaction result {\"trans\":\"eb8b3b48dc363cb2\",\"trace\":\"e5d0c9c95ba516ca673603fecc1415f8\",\"result\":\"HTTP 2xx\"}"}
{"log.level":"debug","@timestamp":"2021-08-13T16:10:12.817Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"could not extract route name from request {\"url\":\"/\",\"type\":\"undefined\",\"null\":false,\"route\":false,\"regex\":false,\"mountstack\":false,\"trans\":\"eb8b3b48dc363cb2\",\"trace\":\"e5d0c9c95ba516ca673603fecc1415f8\"}"}
{"log.level":"debug","@timestamp":"2021-08-13T16:10:12.817Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: GET unknown route {\"trans\":\"eb8b3b48dc363cb2\",\"trace\":\"e5d0c9c95ba516ca673603fecc1415f8\"}"}

alanstorm · August 13, 2021, 4:55pm

Thank you @hsabillon -- we're getting closer. I gave your program a try and I wasn't able to reproduce the issues with Node v14.16.1, koa-router at 10.0.0, and koa at 2.13.1.

Could you let us know the version of node.js you're using, and what version of koa and koa-router you have installed? I suspect we're looking at an older version of the framework and the agent not agreeing with one another on things.

Also -- if you could let us know

What URL are your requesting
Does the URL return the expected hello world message?
Is the URL's status code 200, or is it 404? (or something else?)

hsabillon · August 13, 2021, 5:17pm

@alanstorm Node v14.16.1, koa-router v10.0.0, koa v2.13.1 and elastic-apm-node v3.19.0.

Also on the test:

The URL is http://localhost:3000
Yes, the URL returns the hello world
Status code is 200

alanstorm · August 13, 2021, 6:09pm

Ah -- I think I see what's going on @hsabillon -- could you confirm that you're loading

http://localhost:3000

in a web browser? I was using curl earlier and I missed the issue.

When you request a webpage for the first time in a web browser, two things happen

The browser requests the actual page
The browser also attempts to fetch a favicon file

The GET unknown route transaction name you're seeing is not for your request to http://localhost:3000 -- it's for the request your browser automatically makes to

http://localhost:3000/favicon.ico

Because you don't have a handler for this URL, you get the agent's default handling of a 404 page.

One way to handle this is to add a router for /favicon.ico

router.get('/favicon.ico', (ctx, next) => {
  ctx.response.status = 204
})

The 204 status code says "there's no favicon for this site" -- You could also provide a favicon for your website.

I think that should get you on your way @hsabillon -- but if you still think there's a problem please let us know.

hsabillon · August 13, 2021, 8:05pm

@alanstorm yes I was using a web browser to loading http://localhost:3000 I tried using curl to access the same exact example and I still get the same behavior

{"log.level":"debug","@timestamp":"2021-08-13T19:57:41.203Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"could not extract route name from request {\"url\":\"/\",\"type\":\"undefined\",\"null\":false,\"route\":false,\"regex\":false,\"mountstack\":false,\"trans\":\"3ae6cab4cdbd5e4d\",\"trace\":\"ecc3eb55f15f37a5eaea247c9042ae64\"}"}
{"log.level":"debug","@timestamp":"2021-08-13T19:57:41.203Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"setting default transaction name: GET unknown route {\"trans\":\"3ae6cab4cdbd5e4d\",\"trace\":\"ecc3eb55f15f37a5eaea247c9042ae64\"}"}

it's weird that works for you and not for me.

alanstorm · August 13, 2021, 9:34pm

It is strange -- but everything we rule out means we're one step closer to solving the problem.

I took a closer look at your program and realized I'd missed one bit of configuration. Specifically, I was missing

    instrument: false

When I add this, I'm able to reproduce the behavior you're describing.

So that's one mystery solved.

Can you try setting this to true (or removing it completely) and letting us know if that fixes the problem of getting a GET unknown route transaction name?

If you need this setting set to false, can you let us know why? Per the configuration docs, this turns off our instrumentation of third party modules which disabled a lot of the agent's behavior and can create strange situations like the one we're seeing here.

hsabillon · August 16, 2021, 6:35pm

@alanstorm tried with instrument: false and the code works without the GET unknown route on the transaction name.

But we want to have the instrument: false because we do our instrumentation manually on all our projects following this feature https://github.com/elastic/apm-agent-nodejs/pull/1114 this is working until now with koa and koa-router we get this behavior of GET unknown route

alanstorm · August 16, 2021, 11:57pm

Thank you @hsabillon -- we have enough here now to get a bug opened in the Agent repository (which I've done here: bug: transaction.setDefaultNameFromRequest relies on instrumentation being loaded · Issue #2288 · elastic/apm-agent-nodejs · GitHub)

That said, while I was able to reproduce your error log messages

could not extract route name from request

This error message indicates a problem with setting the default name for a transaction. When my version of your program had apm.setTransactionName('custom name'); in place, the final name reported to Elastic was custom name. In other words, the setTransactionName method call appears to have worked.

Could you confirm that you're seeing the wrong name in your elastic UI and/or that agent payload is being generated with the non-custom-set-name? If you're comfortable with it, an easy way to check your agent payload is to temporarily add a console.log(payload) right here

github.com

elastic/apm-agent-nodejs/blob/c743e2bb8ff3dd31fbfef291ad2b3f33c3019985/lib/instrumentation/index.js#L221


      
            var agent = this._agent
          
            if (agent._conf.disableSend) {
              // Save effort if disableSend=true. This one log.trace related to
              // disableSend is included as a possible log hint to future debugging for
              // why events are not being sent to APM server.
              agent.logger.trace('disableSend: skip sendTransaction')
            } else if (this._started) {
              var payload = agent._transactionFilters.process(transaction._encode())
              if (!payload) return agent.logger.debug('transaction ignored by filter %o', { trans: transaction.id, trace: transaction.traceId })
              agent.logger.debug('sending transaction %o', { trans: transaction.id, trace: transaction.traceId })
              agent._transport.sendTransaction(payload)
            } else {
              agent.logger.debug('ignoring transaction %o', { trans: transaction.id, trace: transaction.traceId })
            }
          }
          
          Instrumentation.prototype.addEndedSpan = function (span) {
            var agent = this._agent
          
            if (agent._conf.disableSend) {

hsabillon · August 17, 2021, 4:01pm

@alanstorm thanks for the bug report! Also tried to log the agent payload on the line you suggested and here is the result

{
  id: '8e13906a23033ad3',
  trace_id: '1132313793a0e0d25ac6dac088de6767',
  parent_id: undefined,
  name: 'custom name',
  type: 'request',
  subtype: null,
  action: null,
  duration: 6.989,
  timestamp: 1629214725875047,
  result: 'HTTP 2xx',
  sampled: true,
  context: {
    user: {},
    tags: {},
    custom: {},
    request: {
      http_version: '1.1',
      method: 'GET',
      url: [Object],
      socket: [Object],
      headers: [Object]
    },
    response: { status_code: 200, headers: [Object] }
  },
  sync: false,
  span_count: { started: 0 },
  outcome: 'success',
  sample_rate: 1
}

on the elastic UI, all the transactions are been generated with GET unknown route and POST unknown route

alanstorm · August 17, 2021, 4:50pm

Hmmm -- I'm having trouble reconciling that with what I see in the logged payload. The payload indicated that transaction's name is getting set to custom name

  name: 'custom name',

If you're not seeing that in the UI there may be something else going on with your system/setup. It could be as simple as looking at the wrong application/date range, or that something is preventing these specific transactions from getting through. If you have more data/information to share from your debugging about that it would be helpful.

hsabillon · August 17, 2021, 5:12pm

My bad @alanstorm I was running without the instrument: false this will be the log for the payload

{
  id: 'fe132f967e0cc747',
  trace_id: '7c969854ea9e1b4c53a257f2c8c3b440',
  parent_id: undefined,
  name: 'GET unknown route',
  type: 'request',
  subtype: null,
  action: null,
  duration: 5194.175,
  timestamp: 1629220041400110,
  result: 'HTTP 2xx',
  sampled: true,
  context: {
    user: {},
    tags: {},
    custom: {},
    request: {
      http_version: '1.1',
      method: 'POST',
      url: [Object],
      socket: [Object],
      headers: [Object]
    },
    response: { status_code: 200, headers: [Object] }
  },
  sync: false,
  span_count: { started: 0 },
  outcome: 'success',
  sample_rate: 1
}

and that name is reflected on the Elastic UI

alanstorm · August 23, 2021, 11:23pm

@hsabillon We've got a WIP PR going to fix this issue that provides a default name when the agent instrumentation isn't loaded. If you could give this branch a try and let us know if it effects the behavior you're seeing it'd be a big help (no worries if not)

github.com/elastic/apm-agent-nodejs

wip: fix for undefined routes when instrumentations are not loaded

elastic:master ← elastic:astorm/uninstrumented-request

opened 11:19PM - 23 Aug 21 UTC

astorm

+27 -0

Issue: https://github.com/elastic/apm-agent-nodejs/issues/2288 WIP -- assigne…d a default route name using the first segment of the raw `IncomeingMessage` path. Not intended to commit as is. ### Checklist - [x] Implement code - [ ] Add tests - [ ] Update TypeScript typings - [ ] Update documentation - [ ] Add CHANGELOG.asciidoc entry - [ ] Commit message follows [commit guidelines](https://github.com/elastic/apm-agent-nodejs/blob/master/CONTRIBUTING.md#commit-message-guidelines)

Also -- for the case where you say

I was running without the instrument: false this will be the log for the payload

Were you calling apm.setTransactionName('custom name') during these calls, or was this an example running without that API call?

hsabillon · August 24, 2021, 9:29pm

@alanstorm tried your WIP PR and the GET unknown route is replaced by a GET / on the transaction name so it's working on the example.

Another interesting thing we noticed is that even with the instrument: false option on the agent, the agent still tries to automatically collect information (I've assume) based on this logs:

{"module":"elastic-apm-node","level":20,"msg":"intercepted request event call to http.Server.prototype.emit for /","time":"2021-08-24T20:59:20.814Z","v":0}
{"module":"elastic-apm-node","level":20,"msg":"start trace {\"trans\":\"90aeefa989de9740\",\"trace\":\"1196249472bb311068ca59ea7ecaad20\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}","time":"2021-08-24T20:20:35.351Z","v":0}
{"module":"elastic-apm-node","level":20,"msg":"start trace {\"trans\":\"de61dcb5f3bb88e5\",\"trace\":\"33c1d33e84e9ed42ea45a323a67e4844\",\"name\":\"unnamed\",\"type\":null,\"subtype\":null,\"action\":null}","time":"2021-08-24T20:20:35.354Z","v":0}

We get two transactions, the second transaction is the one we created manually and renamed with apm.setTransactionName() the first one is the one with the GET / or GET unknown route name.

alanstorm · August 26, 2021, 4:45pm

@hsabillon Ah -- that's useful new information. It sounds like you're saying you want to completely take over the creation of transactions? (Your posts up until now suggested you wanted to disable instrumentation loading, but rename the transactions that the agent starts automatically for you)

If the above is correct could you

Try setting instrumentIncomingHTTPRequests to false (this will disable automatic transaction creation for HTTP requests in the agent)
Let us know if you can rename the transactions you create with the released agent
Let us know if you can rename transaction you create with the WIP fix above

hsabillon · September 3, 2021, 8:27pm

Hi @alanstorm! Just to let you know that instrumentIncomingHTTPRequest: false and the WIP solved all our troubles!

Thanks for all your help.

system · September 24, 2021, 4:28pm

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.