Huge problems with serving bigger site with SPDY

[Rush]

Firstly, I am using node 0.11.9 (will try git) and node-http-proxy#caronte to get the content. I am sure it works all right, I have no problems with it with ordinary https or http. However with node-spdy it seems that the data is being cut in the middle of some requests. Firebug shows lots of requests and aborted and Chrome seems to work a bit better, but flawed as well. While running into problems I get few types of exceptions. I will try to make some "minimal" testcase but I would like to know your opinion as soon as you could give one.

This is the url being run with node-spdy: https://jira-nowaker.atlashost.eu:8443/secure/Dashboard.jspa <- with Firefox it is most apparent and with Chrome it sometimes requires a few refreshes

[Uncought exception] TypeError: Property 'onIncoming' of object #<HTTPParser> is not a function
    at HTTPParser.parserOnHeadersComplete (_http_common.js:111:23)
    at Socket.socketOnData (_http_client.js:272:20)
    at Socket.EventEmitter.emit (events.js:98:17)
    at readableAddChunk (_stream_readable.js:156:16)
    at Socket.Readable.push (_stream_readable.js:123:10)
    at TCP.onread (net.js:509:20)

[Uncought exception] AssertionError: null == true
    at Socket.socketOnData (_http_client.js:270:3)
    at Socket.EventEmitter.emit (events.js:98:17)
    at readableAddChunk (_stream_readable.js:156:16)
    at Socket.Readable.push (_stream_readable.js:123:10)
    at TCP.onread (net.js:509:20)

[Uncought exception] Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:142:15)
    at IncomingMessage.Readable.push (_stream_readable.js:123:10)
    at HTTPParser.parserOnBody (_http_common.js:132:22)
    at Socket.socketOnData (_http_client.js:272:20)
    at Socket.EventEmitter.emit (events.js:98:17)
    at Socket.Readable.read (_stream_readable.js:366:10)
    at Socket.socketCloseListener (_http_client.js:194:10)
    at Socket.EventEmitter.emit (events.js:120:20)
    at TCP.close (net.js:459:12)

[Uncought exception] Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:142:15)
    at IncomingMessage.Readable.push (_stream_readable.js:123:10)
    at HTTPParser.parserOnBody (_http_common.js:132:22)
    at Socket.socketOnData (_http_client.js:272:20)
    at Socket.EventEmitter.emit (events.js:98:17)
    at readableAddChunk (_stream_readable.js:156:16)
    at Socket.Readable.push (_stream_readable.js:123:10)
    at TCP.onread (net.js:509:20)

After testing with git version I get only this exception (but SPDY works as badly as before):

[Uncought exception] Error: stream.push() after EOF
    at readableAddChunk (_stream_readable.js:142:15)
    at IncomingMessage.Readable.push (_stream_readable.js:123:10)
    at HTTPParser.parserOnBody (_http_common.js:132:22)
    at Socket.socketOnData (_http_client.js:277:20)
    at Socket.EventEmitter.emit (events.js:101:17)
    at Socket.Readable.read (_stream_readable.js:366:10)
    at Socket.socketCloseListener (_http_client.js:196:10)
    at Socket.EventEmitter.emit (events.js:123:20)
    at TCP.close (net.js:459:12)

[Nowaker]

It seems batch.js is cut in most cases.

[indutny]

Are you using spdy client?

[indutny]

All errors that you've pasted here are happening in _http_client.js.

[Rush]

Of course SPDY client, otherwise HTTPS would run (and HTTPS works fine) Firefox seems to work most badly: https://jira-nowaker.atlashost.eu:8443/secure/Dashboard.jspa

Browsers work well with Google services (which run on SPDY), HTTPS works otherwise fine so the only other thing in equation is SPDY or otherwise its relation to Node.

[indutny]

@RushPL I meant node-spdy SPDY client, not Chrome's or Firefox's.

[Rush]

https://gist.github.com/RushPL/8146032
Testing with node 0.11.10-pre from git

Requests do fail when running https://localhost:40443
http://x.rushbase.net/0b8c59d7b7bef7812fa52a4e2f1ec953400a8f01/spdyfail.png
Everything is working when running https://localhost:40444 (but ONLY if https is running different config.ssl - I think that node-spdy may be breaking the TLS setup somehow)

Try changing config2.ssl in my gist to config.ssl. :40444 will be broken as well then. Very weird. I think it says that SPDY itself is not broken but somehow SPDY's negotiation is breaking things as testing with broken SNI/SPDY negotiation to HTTPS problem occurs as well.

I have not tried node-spdy client since it needs many concurrent requests for the test to make sense.

[indutny]

@RushPL I fixed config.ssl problem. But that other problem seems to be happening on Chromium's side.

I.e. it terminates connection if the server is sending response before the client has finished sending body. You can fix it in your code by waiting for req.on('end', ...) to happen (NOTE that in node v0.10 and v0.11 you'll need to read from the request stream in order to received 'end' event).

Unfortunately, this doesn't seem to be something that should be fixed on a node-spdy side. I've contacted chromium guys and will try to resolve issue with them.

(Also it seems to be working fine in firefox for me)

[indutny]

Here is a chromium issue link for your reference: https://code.google.com/p/chromium/issues/detail?id=330860&thanks=330860&ts=1388159295

[Rush]

Well, I suggest re-opening the issue until google chrome fixes it because for all practical purposes all parties should make an effort to make a protocol work. Problem is that node-spdy is unusable in Chrome which is a major problem - and hence still an open issue. Every client and every server has some "quirks" and parties often meet in the middle. It is my understanding that whatever works with https.createServer should work with spdy.createServer and hence your req.on("end") advice is impractical since I am using for example third party libraries (node-http-proxy) which require correct behaviour. Replacing https for spdy simply must work for all use cases for your library to be useful. I applaud your effort but let's try to make it work even better.

About firefox - I am sure there is still some major problem, I will try to update the test case.

[indutny]

Well, I'm against reopening this issue and working at around for chromium. Fixing it will introduce major problems for some active node-spdy users that I'm currently consulting.

In my opinion - no hacks in node-spdy just to make non-standard compliant clients works. Even if they are popular clients.

Anyway, considering their release process we may get working chrome version quite soon, if they'll consider working on fixing that issue.

[Rush]

I want to follow up on the Firefox (version 26.0) problem:
https://gist.github.com/RushPL/8149117#file-spdymultiplepostrequests-js

Please notice small request size - firefox is not processing the requests properly:
http://x.rushbase.net/ae59e6dfde64caec87707f1fd861ccac6486ad7d/spdyfail1.png
Also the method: null problem from other issue #124
http://x.rushbase.net/b3ba379b625daa17e7dd65a38bbd2de013b449df/spdyfail2.png

https working well, 5.1MB requests:
http://x.rushbase.net/57d2ad1168682ed3f46a34ea3891ad448e3e53cc/httpsOk.png

[Nowaker]

If that's Chromium problem, then I agree working it around is not a good idea. However, I'd still suggest to open this issue and rename to something like "resources sometimes don't load in Chromium", and keep it open as long as it's not fixed in Chromium. node-spdy users would know in advance that node-spdy should not be used yet when visitors are going to use Chromium. Also, doing so could prevent possible duplicates from being reported.

[indutny]

Okay, okay.

About firefox, the same example seems to be working fine for me.

[Rush]

So you are not getting req.method "null"? also the latest test sends 5.1MB of payload as shown on

(using https)

[indutny]

Yep, sorry. Was testing on previous version of test case. But it seems to be working anyway. And I'm not getting empty methods.

[indutny]

And a

firebug screenshot:

[indutny]

@RushPL can you please try updating to the latest spdy version? I pushed several fixes recently.

[indutny]

1.17.19

[Rush]

Just tried the latest 1.17.19 still the same problem. My previous gist had newlines by mistake, this one fixes it if you had problems. https://gist.github.com/RushPL/8149458#file-spdymultiplepostsperrequests-js

also getting

# node spdyMultiplePostRequests.js
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null
BAD req.method!! null

which is probably why the POST never runs and payload is so small

> node --version
v0.11.10-pre

> firefox --version
Mozilla Firefox 26.0

> cat node_modules/spdy/package.json|grep \"version\"
  "version": "1.17.19",

Anything I may be missing?

[Nowaker]

Just tried 1.17.19. Firebug console is green on my side, but the response is not what we expect (req.method == "POST" is false). There is a lot of BAD req.method!! null in the console.

Happens both in:

• Firefox 21 (the screenshot above)
• Firefox 26
• Chrome 31.0.1650.63 (some responses are red, Chrome issue)

[Nowaker]

I am using node-git from master, built moments ago. v0.11.10-pre

[indutny]

how is it related to node-git? Your test case isn't using it.

I'm using Firefox 26 and it seems to be fine here too...

[indutny]

Also, spdy@1.17.19 has explicit check for presence of method in client's request.

If you have time - may I ask you to try patching your local node-spdy version (in node_modules) and adding console.log(frame) right before this line https://github.com/indutny/node-spdy/blob/master/lib/spdy/connection.js#L289 ?

[Nowaker]

There you go. https://wklej.stratushost.eu/hash/f355d7174d8/

[Nowaker]

I totally removed those AJAX requests from the minimal code. They are not needed to get req.method == null.

I changed your code this way:

  console.log('BEGIN');
  console.log(frame.headers.method);
  this.emit('stream', stream);
  console.log(frame.headers.method);
  stream._start(frame.url, frame.headers);
  console.log(frame.headers.method);
  console.log('END');
  return stream;

The output:

BEGIN
GET
GET
BAD req.method!! null
GET
END

This could lead to a conclusion that req.method is null somewhere in stream._start(frame.url, frame.headers);.

[indutny]

Indeed, may I ask you to long info object there: https://github.com/indutny/node-spdy/blob/master/lib/spdy/stream.js#L232 ?

[Nowaker]

Sure thing!

Updated test case: https://gist.github.com/Nowaker/8149829/raw/bd8b49a4bd76ee21a735eb936603b91d4405eed0/spdyMultiplePostsPerRequests.js

Output:

BEGIN
GET
GET
{ url: '/',
  headers: 
   [ 'host',
     'localhost:40443',
     'user-agent',
     'Mozilla/5.0 (X11; Linux x86_64; rv:26.0) Gecko/20100101 Firefox/26.0',
     'accept',
     'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-language',
     'en-US,en;q=0.5',
     'cache-control',
     'max-age=0' ],
  versionMajor: 1,
  versionMinor: 1,
  method: 'GET',
  statusCode: false,
  upgrade: false }
Request method is: null
GET
END

Changed your code to:

  // connection.js
  console.log('BEGIN');
  console.log("connection.js 1: " + frame.headers.method);
  this.emit('stream', stream);
  console.log("connection.js 2: " + frame.headers.method);
  stream._start(frame.url, frame.headers);
  console.log("connection.js 3: " + frame.headers.method);
  console.log('END');

  // stream.js
  console.log("1: " + info.method);
  var onHeadersComplete = this._parserHeadersComplete();
  console.log("2: " + info.method);
  if (onHeadersComplete) {
    onHeadersComplete.call(this.parser, info);
    console.log("3a: " + info.method);
  } else {
    this.emit('headersComplete', info);
    console.log("3b: " + info.method);
  }

Output:

BEGIN
connection.js 1: GET
connection.js 2: GET
{ url: '/',
  headers: 
   [ 'host',
     'localhost:40443',
     'user-agent',
     'Mozilla/5.0 (X11; Linux x86_64; rv:26.0) Gecko/20100101 Firefox/26.0',
     'accept',
     'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
     'accept-language',
     'en-US,en;q=0.5',
     'cache-control',
     'max-age=0' ],
  versionMajor: 1,
  versionMinor: 1,
  method: 'GET',
  statusCode: false,
  upgrade: false }
stream.js 1: GET
stream.js 2: GET
Request method is: null
stream.js 3a: GET
connection.js 3: GET
END

Still not here :)

[indutny]

Oh, I know what's happening one sec. It is a new node.js 0.11 thing :P

[indutny]

Thank you, fixed! What about this issue?

[indutny]

Oh wait, it wasn't fixed... I think I need to patch node.js first haha :P

[Nowaker]

Yeah, just wanted to tell you my GET turned out to be PUT. xD

[indutny]

Yeah yeah, I know. Please try spdy@1.17.21

[Nowaker]

Indeed, 21 is OK now. Let me install it in production at https://jira-nowaker.atlashost.eu:8443/secure/Dashboard.jspa.

[Nowaker]

Works in production. Thank you very much for digging into it!

So what's only left is Chromium issue, right?

[indutny]

Right.

[Rush]

I see the Chromium devs have fixed the issue - thanks for the great help Fedor. Do you think that there is a possibility to conditionally enable SPDY after certain Chromium version? Do you even have such version information at the moment of doing NPN? I am sceptical about this but I would like to enable SPDY by default only to 100% correctly behaving clients.

[indutny]

No, I'm afraid this is not possible.

[indutny]

@RushPL does it still happens to you on a newer Chrome?

[Rush]

Seems good to me! I'd like @Nowaker to try it as well and if it's good we'll close the issue.

[Nowaker]

I have enabled SPDY for my private JIRA and it seems okay on my Chrome 34.

I will still refrain from enabling SPDY for all AtlasHost customers as some may have not yet updated their browsers... but I will enable it later this year. Thanks @indutny for your help.