TypeError: Failed to decode param ''

[MichaelHedman]

We have a nodejs app running on Heroku, and sometimes, without warning, all requests on a specific web dyno start to fail with a 400 Bad Request response. In the logs we can see entries like this:

TypeError: Failed to decode param '' at decode_param (/app/node_modules/express/lib/router/layer.js:162:15)

Restarting the app usually helps, but not always. Any idea what could be wrong?

Our package.json dependencies:

"dependencies": {
    "body-parser": "^1.12.2",
    "compression": "^1.4.3",
    "ejs": "~1.0.0",
    "errorhandler": "^1.0.0",
    "express": "~4.12.3",
    "extend": "1.2.1",
    "forever": "^0.14.1",
    "jslint": "^0.3.1",
    "mandrill-api": "^1.0.39",
    "newrelic": "1.17.2",
    "querystring": "^0.2.0",
    "request": "2.29.0",
    "requirejs": "^2.1.16",
    "ws": "^0.4.32"
  },

We haven't been able to reproduce or trigger this error in a test environment. Since this error is thrown by decodeURIComponent, we thought that we were missing some encoding. But after setting LANG=en_US.UTF-8 the problem still occurs. We have also tried running the app on a local ubuntu vagrant image after removing all installed locales, but that didn't trigger the problem either.

[dougwilson]

Hmm, I have never seen that before. Anyway to provide code to reproduce? Otherwise it's hard to do anything other than await a PR :(

[dougwilson]

My only real guess at this point is something you are loading is overwriting the decodeURIComponent global function and changing it's behavior? If you can capture what the actual thrown error from the decodeURIComponent call is and paste it there, that may help, but otherwise there isn't anything for us to act on right now.

[MichaelHedman]

We've now been able to trigger the error in a test environment (also on heroku). We are able to trigger it if we run siege or jmeter against the app with a lot of requests, and at the same time repeatedly restarting the app (with the pre-boot option disabled).

But printing the error:
console.log("- - -" + JSON.stringify(e));
gives us:

• - -"illegal access"
  This makes it really tricky to debug. Any tips on how to inspect the error?

[dougwilson]

As far as I can tell, that illegal access error from decodeURIComponent is a v8 bug. What version of Node.js are you running?

[dougwilson]

It could also very well be that your JSON.stringify(e) call is triggering the bug https://code.google.com/p/v8/issues/detail?id=2397 , so that error may not even be the error coming from decodeURIComponent. Can you log the error a different way?

[MichaelHedman]

We thought of that too. But we're not sure because "illegal access" is actually thrown by ThrowIllegalOperation() in some instances. The only explicit error thrown in uri.js (in v8) is URIError.

Right now we rely on "heroku logs" and LogEntries. We need to get more verbose output from v8 to be able to proceed. A stack trace from within v8 for example.

[MichaelHedman]

By the way, now we have removed the JSON.stringify(e), and that is not where we cause the error to be thrown. It comes from decodeURIComponent. And our node version is 0.12.3.

[dougwilson]

Gotcha. Hm, that still is really weird, though I don't think it's anything Express can do to fix decodeURIComponent, no?

[MichaelHedman]

We observe that express/node/V8 ends up in a weird state sometimes when the app (dyno at Heroku) is restarted under heavy load. Our suspicion is that something is not properly initialised when the first requests come in. Is it conceivable that this can happen?

[dougwilson]

I'm not sure. There really is no initialization done by Express at all, especially anything that would affect a built-in like decodeURIComponent. It is known that Node.js 0.12 uses a buggy v8 version, so it's also possible (in my mind) that this is a Node.js 0.12 bug. You can eliminate that possibility by trying on a different Node.js version, of course.

[MichaelHedman]

We currently run 0.12.3 that actually includes an "older" v8 version. From the node changelog:
2015.05.13, Version 0.12.3 (Stable)

• V8: update to 3.28.71.19

[MichaelHedman]

But we could of course try an older node version like 0.10.x and see if we're able to reproduce it.

[MichaelHedman]

We have reverted to node v0.11.14 (which has v8 version 3.26.33, and is also the last version before the 3.28.73 and 3.28.71.19 v8 versions) and have so far not been able to trigger the error. We will run this in production over the weekend and monitor it closely.

[MichaelHedman]

We have now been running on node 0.11.14 since Thursday (4 days) without any errors, so we're pretty confident that the problem lies in v8 or further down the stack.

Unfortunately we are only able to reproduce the error when we run the app on Heroku, which makes it really difficult to investigate since the dynos are pretty much a black box. The problem could be in v8, or somewhere in the Heroku cedar stack.

How do you suggest we proceed?

[dougwilson]

I have been looking around online and have not found anything useful. One guess is that you may need to use the same CPU arch as the dyno to reproduce it, potentially (at least 32 vs 64-bit), in case it's an issue with v8 machine instruction generation. Otherwise, you may want to reach out to the Node.js team for help digging in, as this is likely to be outside my knowledge area :/