Lots of AssertionErrors

[devongovett]

We (Storify) are seeing lots of AssertionErrors being thrown, technically by node-continuation-local-storage but resulting from use by node-newrelic. These are causing uncaught exceptions on our servers. Here's an example stack trace:

AssertionError: context not currently entered; can't exit
    at Namespace.exit (/data/storify/webapp/node_modules/newrelic/node_modules/continuation-local-storage/context.js:78:10)
    at Namespace.bind (/data/storify/webapp/node_modules/newrelic/node_modules/continuation-local-storage/context.js:53:12)
    at Tracer.monitor (/data/storify/webapp/node_modules/newrelic/lib/transaction/tracer.js:239:22)
    at ErrorTracer.monitor (/data/storify/webapp/node_modules/newrelic/lib/error.js:189:12)
    at Tracer.monitor (/data/storify/webapp/node_modules/newrelic/lib/transaction/tracer.js:237:28)
    at wrapCallbackInvocation (/data/storify/webapp/node_modules/newrelic/lib/transaction/tracer.js:179:17)
    at ServerResponse.res.render (/data/storify/webapp/node_modules/express/lib/view.js:322:7)
    at ServerResponse.render (/data/storify/webapp/node_modules/newrelic/lib/instrumentation/express.js:116:21)

I'm not exactly sure what the problem is, but it would be awesome if those errors could be caught. Thanks so much! Let me know if there is anything I can do to help.

[othiym23]

Thanks for the report! This is actually a dupe of #61, and is fixed in version 0.11.9 of the agent. tl;dr: writing an asynchronous transaction tracer is hard. In any case, give 0.11.9 a shot, and reopen / file a new ticket if you're still seeing issues. Thanks!

[Philmod]

Hi, we are using the v0.11.9. cc @devongovett

[othiym23]

This is a fiendishly hard issue to reproduce -- can you provide enough of a subset of your code that we can use for local debugging? At the very least, I'd like to know what your Express configuration looks like and know whether this happens on specific routes or for specific HTTP methods, or whether it's distributed evenly across your entire app. If you have stuff that we could use for local debugging that you don't feel comfortable posting on GitHub, you can send it to [email protected], where it will only be seen by me and my team. Thanks!

[Philmod]

We are using express 2.5.8.
Interesting, it's happening when we have a .jade error :

TypeError: /data/storify/webapp/config/../app/views/story/_story.jade:128
...
Oct 14 14:13:39 storify-webapp02 errors.log:  Cannot read property 'comments' of undefined
Oct 14 14:13:39 storify-webapp02 errors.log:      at eval (eval at <anonymous> (/data/storify/webapp/node_modules/jade/lib/jade.js:160:8))
...
Oct 14 14:13:39 storify-webapp02 access.log:  Oct 14 14:13:39 - ERROR - uncaughtException - AssertionError: context not currently entered; can't exit

Does that help you?

Otherwise, feel free to ask me more.

[devongovett]

Also Node v0.8.20 if that makes a difference.

[othiym23]

Thanks guys, that does totally help. Can you do me a favor? If you could run something like this:

cd node_modules/newrelic/node_modules/continuation-local-storage
npm install [email protected]

And then see if it breaks in the same way? This weekend I made a bunch of changes to how the async listener code deals with errors, and there's a decent chance it will make this throw in a more predictable way (i.e. more like how it was behaving before the newrelic module was introduced). Thanks!

[Philmod]

Ok, I do that. But I haven't seen a lot this error today, as I left new relic module only on one box.

Ping me tomorrow at the end of the day, I'll search in the logs to see if it happened again.

Well, I couldn't do it :

npm WARN optional dep failed, continuing [email protected]

[othiym23]

Could you make a gist of npm-debug.log and link to it here? I just tried those exact steps and it worked for me, so there's either something weird going on with npm or your connection to npm (or maybe 0.8.20 is causing problems). Thanks for your patience!

[Philmod]

I can't find these logs.
Even after changing the module version in the package.json, same error.

[othiym23]

This may be a 0.8-specific thing. I haven't done a lot of testing of the the error-handling bits of async-listener under 0.8.x. I'll look into that further.

Is there a specific reason you haven't upgraded to Node 0.10? New Relic does support Node 0.8, so we'll need to fix this sooner or later, but I'd like to get you guys past this problem.

[Philmod]

We should upgrade to Node 0.10 for the webapp, but I need to test it more before.

[othiym23]

OK! I wanted to know because there are customers with specific blockers (stability, the streams2 changes) that have prevented them from being able to upgrade. I'll see if I can figure out what's going on with 0.8.20. As I said this morning, a code snippet that reproducibly causes this error would be very helpful, but if you can't provide one or don't have the time, I'll continue to see what I can do on New Relic's end.

[Philmod]

I've just upgraded the module as you asked, it was just a permission issue,
sorry about that.

I'll tell you tomorrow if I see errors.

On 14 October 2013 20:02, Forrest L Norvell [email protected]:

OK! I wanted to know because there are customers with specific blockers
(stability, the streams2 changes) that have prevented them from being able
to upgrade. I'll see if I can figure out what's going on with 0.8.20. As I
said this morning, a code snippet that reproducibly causes this error would
be very helpful, but if you can't provide one or don't have the time, I'll
continue to see what I can do on New Relic's end.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/62#issuecomment-26306233
.

Philippe Modard
415-722-1245
[email protected] [email protected]
twitter.com/philmod
re.vu/philippemodard
www.linkedin.com/in/philippemodard
IBAN BE70 0639 3284 8025 - BIC: GKCCBEBB

[Philmod]

I had a lot of errors like

Oct 14 21:00:07 - ERROR - uncaughtException - Error: Can't set headers after they are sent.

after having upgraded the module you told me.

I had to remove new relic completely.

Keep me updated.

[othiym23]

I had to do some significant surgery on one of newrelic's dependencies to make it handle errors properly in node 0.8, but I believe I have a working fix. I want one of my colleagues to test and review it before we push out a new version of the module, but we'll do that by the end of the day today. Thanks for your patience!

[othiym23]

I believe that othiym23/async-listener@d202af8 and othiym23/async-listener@6ae7430 fix this issue. Please let me know if the new build of the agent still has issues, and thanks for your patience!

[mike-lang]

Today I'm seeing floods of the "Can't set headers after they are sent" error in one of my environments. I'm not sure what I've done to trigger the "No Express route to use for naming" error either. I've not added any new routes recently and I've had new-relic in place for weeks. We started naming some of our transactions last week, but have not removed any explicitly set names.

I'm using module version "1.2.0", and my logs are filled with entry pairs like these:

:43.498898+00:00 app web.1 - - Error: Can't set headers after they are sent. at ServerResponse.OutgoingMessage.setHeader (http.js:679:11) at ServerResponse.res.setHeader (/app/node_modules/express/node_modules/connect/lib/patch.js:62:20) at next (/app/node_modules/express/node_modules/connect/lib/http.js:166:13) at Namespace.bind (/app/node_modules/newrelic/node_modules/continuation-local-storage/context.js:62:17) at pass (/app/node_modules/express/lib/router/index.js:219:24) at nextRoute (/app/node_modules/express/lib/router/index.js:209:7) at callbacks (/app/node_modules/express/lib/router/index.js:274:11) at callbacks (/app/node_modules/express/lib/router/index.js:277:9) at callbacks (/app/node_modules/express/lib/router/index.js:277:9) at callbacks (/app/node_modules/express/lib/router/index.js:277:9) EXCEPT
» 16:56:45.007 2013-12-19 22:56:43.499108+00:00 app web.1 - -

{"name":"newrelic","hostname":"a52703bf-eee1-4151-a70d-dbd9c672858d","pid":2,"component":"express","level":50,"msg":"No Express route to use for naming.","time":"2013-12-19T22:56:43.498Z","v":0}
» 16:56:45.007 2013-12-19 22:56

[othiym23]

Thanks for the comment, but I'm afraid there isn't really enough data in your comment to say for sure what's going on. If 1.2.0 was working before and is throwing up now, did one of the module versions in your app change? Did you change how New Relic is required or configured?

It sounds like something has gotten badly out of order inside Connect, but New Relic itself doesn't touch the request and response objects used by Express in a way that would fail this way.

Let us know the answers to these questions and we'll see if we can help you out.

[mike-lang]

I've tracked down the root cause that triggered the flood of errors.

Our application had a bug in it that caused it to first respond to the to the client with a 404 error, and then later attempt to send a 200 response. This generated the initial error, causing express's code to attempt to set headers after they'd initially gone out.

Somehow - and I'm unable to devote the time right now to understanding why this happened - but somehow this particular bug triggered a flood of errors.

I barely understand this code at this point, but it look as if the try finally block here:

https://github.com/othiym23/node-continuation-local-storage/blob/v2.5.2/context.js#L56

may possibly let an exception escape that may get processed in a way that on the next round of the event loop, this logic gets invoked and processes yet again in a context where there is no route name, trigger the same error, and so an and so forth until the original error has resulted in 300000 error entries getting logged in the span of 3 minutes and manual interventions are employed.

Like stated, I couldn't finish the analysis, but thought I'd relate where things seemed to point for whatever it may be worth. Perhaps this is in an accurate description of what is happening and there is a way to detect this cycle and prevent it from perpetuating? Anyways, I hope it helps. The emergence of this sort of behavior is a concern to us and I'd imagine other clients may feel similarly.

Regards,
Mike

[othiym23]

The try-finally block is explicitly designed to not catch any errors that pass through it. Its job is to ensure that the CLS namespace is exited properly regardless of whether or not there are any exceptions thrown in the bound function.

CLS and the asyncListener don't actually defer anything to future ticks. When it comes to errors, their job is to be as transparent as possible and not alter how your program crashed.

The code is complex enough that I'm prepared to believe something weird could be happening, but I need more to go on. Can you produce a repro case?

Thanks for the research and your persistence thus far!