No transaction found when setting controller name

[acroca]

I have an Express app and, in a middleware, I set the controller name and action to newrelic. Randomly it logs the following message:

{"name":"newrelic","hostname":"...","pid":13935,"component":"api","level":40,"msg":"No transaction found when setting controller to users.","time":"2013-10-29T09:49:02.051Z","v":0}

In newrelic I get some transactions with controller#action, some with the normalized URL and some with just /*.

[othiym23]

Thanks for the report! We haven't seen this particular behavior before. It sounds like the way your middleware stack is configured is causing the transaction-naming API to be called outside of the context of the New Relic transaction tracer sometimes. Given the way the tracer works, it should either fail all the time or none of the time, so that "sometimes" is especially problematic.

Is there any chance you could paste your Express middleware configuration, or even better, a reduced test case (3rd party dependencies are fine / expected)? Also, are you seeing any other errors related to New Relic?

[acroca]

It's something like this:

app = express()
app.use allowCrossDomain # just sets some headers
app.use app.router
app.use errors.middleware # Handles errors on the controller, etc

A route will look like this:

user_show_middlewares = [
  time_logger #Processes the response time and sends to the log.
  body_parser
  signer # validates requests based on some headers
  authentication # Sets the current_user to the req based on the request token
  (req, res, next) ->
    newrelic.setControllerName('users', 'show')
  controllers.user.show # This is the action itself.
] 
app.get('/v1/users/:id', user_show_middlewares)

The actual code is a bit more complicated but this is basically what ends happening from the express point of view.

How does newrelic to know what's the current request when I call newrelic.setControllerName? If there are multiple transactions happening at the same time I don't know how it's going to know to which transaction set the controller name.

Thanks!

[othiym23]

Is there a reason you're using the Connect router? We don't actually instrument that because it's been deprecated. You should be able to comment out the app.use app.router line and have things continue to work, and then our module will be less likely to get confused.

The module knows what the current request is because it's using a module called continuation-local-storage that passes state through a particular chain of function calls. Check out its repo if you want to know more about what it is and how it works.

Let me know if pulling the Connect middleware out of the stack makes things any less confusing.

[acroca]

Ok, cool. I don't remember why that line is there, will try without and reply.

Thanks!

Albert Callarisa Roca

On Wednesday, 30 October, 2013 at 10:05 am, Forrest L Norvell wrote:

Is there a reason you're using the Connect controller? We don't actually instrument that because it's been deprecated. You should be able to comment out the app.use app.router line and have things continue to work, and then our module will be less likely to get confused.
The module knows what the current request is because it's using a module called continuation-local-storage that passes state through a particular chain of function calls. Check out its repo (https://github.com/othiym23/node-continuation-local-storage) if you want to know more about what it is and how it works.
Let me know if pulling the Connect middleware out of the stack makes things any less confusing.

—
Reply to this email directly or view it on GitHub (#73 (comment)).

[acroca]

Tried something like:

app = express()
app.use allowCrossDomain # just sets some headers
user_show_middlewares = [
  time_logger #Processes the response time and sends to the log.
  body_parser
  signer # validates requests based on some headers
  authentication # Sets the current_user to the req based on the request token
  (req, res, next) ->
    newrelic.setControllerName('users', 'show')
  controllers.user.show # This is the action itself.
] 
app.get('/v1/users/:id', user_show_middlewares)
app.use errors.middleware # Handles errors on the controller, etc

Same error on the logs, same result on newrelic. Most of the transactions has no controller/action name, somehow a few of them have. Also some requests went to /*.

[othiym23]

I'll see if we can reproduce this locally. We don't really have much coverage around setting the transaction name inline like that. I'd still like to know what's causing it to behave differently on different requests, though. Have you noticed any correlation between request paths and how they get named?

[acroca]

I think I found a pattern. The only requests that are setting the controller name and action name are the ones that doesn't have any token (create users and create sessions). The rest are failing.

I added ignore_params: ['token'] to the config but still No transaction found when setting controller to...

Also I still get a lot of /*. Could it be the OPTIONS requests? we finish that requests earlier, in the allowCrossdomain middleware.

Thanks!

Albert Callarisa Roca

On Wednesday, 30 October, 2013 at 12:19 pm, Forrest L Norvell wrote:

I'll see if we can reproduce this locally. We don't really have much coverage around setting the transaction name inline like that. I'd still like to know what's causing it to behave differently on different requests, though. Have you noticed any correlation between request paths and how they get named?

—
Reply to this email directly or view it on GitHub (#73 (comment)).

[acroca]

BTW, the authenticated requests have also 3 headers (plus the token in the params).

Albert Callarisa Roca

On Wednesday, 30 October, 2013 at 1:58 pm, Albert Callarisa Roca wrote:

I think I found a pattern. The only requests that are setting the controller name and action name are the ones that doesn't have any token (create users and create sessions). The rest are failing.

I added ignore_params: ['token'] to the config but still No transaction found when setting controller to...

Also I still get a lot of /*. Could it be the OPTIONS requests? we finish that requests earlier, in the allowCrossdomain middleware.

Thanks!

Albert Callarisa Roca

On Wednesday, 30 October, 2013 at 12:19 pm, Forrest L Norvell wrote:

I'll see if we can reproduce this locally. We don't really have much coverage around setting the transaction name inline like that. I'd still like to know what's causing it to behave differently on different requests, though. Have you noticed any correlation between request paths and how they get named?

—
Reply to this email directly or view it on GitHub (#73 (comment)).

[othiym23]

I created a sample app that builds on what you've told me about your app, and the transaction naming is working as expected there. If there's more detail you can give me about how the tokens are created and validated (or just fork and expand that gist), maybe that will help us figure out what's going on.

If you have a custom middleware that's handling those OPTION requests that's not using an Express named route, they will almost definitely be normalized to /* -- the agent measures all HTTP requests, regardless of method. The naming logic is sort of complicated, but the way it works is described here (with some additional detail later on in that issue).

I added ignore_params: ['token'] to the config but still No transaction found when setting controller to...

Configuring parameters to be ignored only works when capture_params is set to true and Express is already handling a request. Also, it doesn't deal with HTTP headers, only query parameters. So that won't work, unfortunately.

New Relic doesn't directly touch the headers at any point, either to read them or to alter them. It seems like the issue here is related to control flow, and maybe our documentation not being as clear as it could be about how transaction naming works. Does what I've explained so far make things any clearer?

[acroca]

Ok, let me play with it and try to replicate.

Thanks man!

Albert Callarisa Roca

On Wednesday, 30 October, 2013 at 2:34 pm, Forrest L Norvell wrote:

I created a sample app (https://gist.github.com/othiym23/7227790) that builds on what you've told me about your app, and the transaction naming is working as expected there. If there's more detail you can give me about how the tokens are created and validated (or just fork and expand that gist), maybe that will help us figure out what's going on.
If you have a custom middleware that's handling those OPTION requests that's not using an Express named route, they will almost definitely be normalized to /* -- the agent measures all HTTP requests, regardless of method. The naming logic is sort of complicated, but the way it works is described here (#69 (comment)) (with some additional detail later on in that issue).

I added ignore_params: ['token'] to the config but still No transaction found when setting controller to...

Configuring parameters to be ignored only works when capture_params is set to true and Express is already handling a request. Also, it doesn't deal with HTTP headers, only query parameters. So that won't work, unfortunately.
New Relic doesn't directly touch the headers at any point, either to read them or to alter them. It seems like the issue here is related to control flow, and maybe our documentation not being as clear as it could be about how transaction naming works. Does what I've explained so far make things any clearer?

—
Reply to this email directly or view it on GitHub (#73 (comment)).

[acroca]

I forked the gist to something more like the current, but doesn't fail.
I'll debug deeper in the app trying to find the issue.

[acroca]

I found the issue. I just moved the require('newrelic') to the begining of the app, even before requiring express or anything else. Then it worked fine.
I still get some /* and /v1/users/*, but I think they are the OPTIONS requests. I guess I should just ignore them, or just call setTransactionName('options') in this case.

I just saw the line that says Please note that you still need to ensure that loading the New Relic module is the first thing your application does, so I apologize for the bug report, my mistake.

[othiym23]

I'm glad you figured it out!

I just saw the line that says Please note that you still need to ensure that loading the New Relic module is the first thing your application does, so I apologize for the bug report, my mistake.

I should have asked you that first thing, so that's my bad. We're still figuring out how to support this thing! Thanks for working with me and thanks for your patience!