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 :/

[dougwilson]

Hi @MichaelHedman any updates? Is there anything determined that Express can change to address this, or is it boiled down to a Node.js bug (is there a bug report to Node.js?)?

[dougwilson]

Closing, as I haven't hear back here and I don't see what Express can really do about machine code corruption in v8.

[lmarkus]

We recently started getting this error as well (out of the blue) this week.
Running on Node 0.12.4 on

LSB Version:    :core-4.0-amd64:core-4.0-ia32:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-ia32:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-ia32:printing-4.0-noarch
Distributor ID: RedHatEnterpriseServer
Description:    Red Hat Enterprise Linux Server release 5.4 (Tikanga)
Release:    5.4
Codename:   Tikanga

These are production boxes, so we are pretty limited as far as testing on them.
We'll try to reproduce a similar setup, and see if we can hit the same error.

[dougwilson]

For those that are getting this error, it would be useful to also open an issue up on the Node.js repo, as this looks like it's actually a v8 bug, which isn't too surprising, as Node.js 0.12 chose a version of v8 that is pretty buggy. A core v8 function (like decodeURIComponent) throwing the error illegal access as is the case here, is a signal that the machine code v8 generated for decodeURIComponent is invalid or corrupted in some way.

[dougwilson]

There is something Express can do, though: instead of just catching any error from decodeURIComponent and turning it into a 400, we can just only change the actual parse errors into 400s and let anything else (like illegal access bubble up as a 500). This could also be why not a lot of people have noticed it yet when using 0.12.

[dougwilson]

Ok everyone, starting with Express 4.13, non-legitimate errors from decodeURIComponent no longer come though as a 400, instead the original error will correctly bubble up, making the issue easier to identify.

[lmarkus]

Thanks! Sounds good.
I'll go and make some noise on the NodeJS side as well.
Do you guys have a rough eta for the 4.13 milestone, so we can go back to our logs then?

[dougwilson]

Do you guys have a rough eta for the 4.13 milestone, so we can go back to our logs then?

4.13 actually comes out tonight, U.S. Eastern time :) You can also look at the release details and what's in it at #2682

[lmarkus]

👍 Thanks.
We might not be able to deploy to production for a few days.
I'll update as soon as I can.

[lmarkus]

We deployed today, and the error does indeed bubble up. Still not much help in resolving it though.
A quick question, the Node guys asked us to log the parameters that might be causing this.
Other than req.body, what other information could we dump that would help identify/reproduce the error?

[dougwilson]

The parameter is between the single quotes in the error message we used to give with the 400; otherwise the only way to even get that information is to modify Express source code to change https://github.com/strongloop/express/blob/4.13.0/lib/router/layer.js#L169-L172 to the following:

    if (err instanceof URIError) {
      err.message = 'Failed to decode param \'' + val + '\'';
      err.status = err.statusCode = 400;
    } else {
      // log this somewhere
      console.log(new Buffer(val, 'utf8').toString('hex'))
    }

[lmarkus]

Thanks. Still haven't been able to deploy this...
Hope to update soon

[msukmanowsky]

After reading this and this, I'm wondering why express doesn't just use querystring's unescape() method which seems to have better handling for hex that doesn't map to a UTF-8 character.

> var badParam = '<%Site:Name$l>';
> decodeURIComponent(badParam); // throws URIError: URI malformed
    at decodeURIComponent (native)
    at repl:1:20
    at REPLServer.defaultEval (repl.js:132:27)
    at bound (domain.js:254:14)
    at REPLServer.runBound [as eval] (domain.js:267:12)
    at REPLServer.<anonymous> (repl.js:279:12)
    at REPLServer.emit (events.js:107:17)
    at REPLServer.Interface._onLine (readline.js:214:10)
    at REPLServer.Interface._line (readline.js:553:8)
    at REPLServer.Interface._ttyWrite (readline.js:830:14)
> var qs = require('querystring');
> qs.unescape(badParam)
'<%Site:Name$l>'

Can just swap out decode_param for qs.unescape, no?

[dougwilson]

Hi @msukmanowsky ! This issues is only for the Node.js 0.12 issue, please do not hijack the issue :) As far as your question, you can search through issues on old discussion on this and the answer is no, we will not change it for various reasons. You can always open a new issue if you cannot find the old discussions about this.

[msukmanowsky]

Wasn't an attempt to hijack anything. We're hitting this same issue in production where it happens that the internet doesn't always conform to RFC 3986 by strictly passing UTF-8 octets in strings.

After reading #2384 I can see one recommendation is simply to override express' query parser via app.set('query parser', ...). That feedback would've been appreciated as opposed to an accusation of hijacking a discussion.

[dougwilson]

Hi again, @msukmanowsky ! I'm sorry if you were confused, but you are explaining exactly why it is a "hijack". To summarize up all the posts above, this issue is specifically about an issue in the version of v8 that ships with Node.js 0.12 where correctly valid UTF-8-encoded strings to encodeURIComponent will throw because of corrupted machine code. Your basically proposing "hey, encodeURIComponent is broken in Node.js 0.12, so how about completely changing how param decoding works by paring with something different that is also more liberal?"

The this is: we purposely do not want to accept non-RFC2986 parameter values. It was a choice on purpose. If you are proposing a change to make that different or configurable, it's a new issue that needs to be in an issue that is actually open (this is a closed issue) and then discussed by the community of Express so it's decided to be in the best interest. Please create a new issue (or, preferably, a PR) with your proposal so discussions can begin around it. You can always link to this issue if you think the v8 machine corruption issue plays into this.