spdy-http2 / node-spdy

SPDY server on Node.js
2.8k stars 196 forks source link

Error: New stream after GOAWAY #213

Closed gx0r closed 9 years ago

gx0r commented 9 years ago

Getting the following with rc1. Chrome says "Failed to load resource: net::ERR_SPDY_COMPRESSION_ERROR"

  Error: New stream after GOAWAY
      at /home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/connection.js:615:26
      at Array.forEach (native)
      at Connection._goaway (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/connection.js:607:33)
      at Connection.handleGoaway [as _handleGoaway] (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/connection.js:512:8)
      at Connection._handleFrame (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/connection.js:304:10)
      at Parser.<anonymous> (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/connection.js:149:10)
      at emitOne (events.js:77:13)
      at Parser.emit (events.js:169:7)
      at readableAddChunk (/home/u/app/node_modules/spdy/node_modules/spdy-transport/node_modules/readable-stream/lib/_stream_readable.js:198:16)
      at Parser.Readable.push (/home/u/app/node_modules/spdy/node_modules/spdy-transport/node_modules/readable-stream/lib/_stream_readable.js:162:10)
      at Parser.Transform.push (/home/u/app/node_modules/spdy/node_modules/spdy-transport/node_modules/readable-stream/lib/_stream_transform.js:133:32)
      at next (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/protocol/base/parser.js:52:12)
      at /home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/protocol/http2/parser.js:70:5
      at Parser.onGoawayFrame (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/protocol/http2/parser.js:460:3)
      at Parser.onFrameBody (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/protocol/http2/parser.js:151:10)
      at Parser.execute (/home/u/app/node_modules/spdy/node_modules/spdy-transport/lib/spdy-transport/protocol/http2/parser.js:63:8)
indutny commented 9 years ago

@llambda interesting! Do you have a test case? I'm particularly interested in the headers that might be sent to the browser.

Did it crash?

gx0r commented 9 years ago

Not sure if it crashed, was running under nodemon with autorestart. Unfortunately I haven't been able to reproduce the "New stream after GOAWAY", but I do get ERR_SPDY_COMPRESSION_ERROR consistently though.

indutny commented 9 years ago

@llambda do you think it might be possible to know the headers that were sent by your application? Or maybe a tcpdump either of client or server side?

indutny commented 9 years ago

Nah, ignore tcpdump this is TLS. It is all encrypted.

gx0r commented 9 years ago

Authorization: Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJwaG9uZW51bWJlciI6IjU1NTU1NTU1NTUiLCJpYXQiOjE0MzkyNjE4OTl9.WAPTyd0puz1g9hBEk4IOr_PY5g8Ze8ZXNQsAV4xiwCI Referer: https://localhost:8443/?/conversations User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/44.0.2403.130 Safari/537.36 X-Requested-With: XMLHttpRequest

gx0r commented 9 years ago

(Unfortunately, Chrome only gives "Provisional headers are shown", that's all the headers I could see on the failed request.)

indutny commented 9 years ago

@llambda I was actually talking about response headers that were sent by server.

gx0r commented 9 years ago

Unfortunately Chrome doesn't show any, neither does firefox.

indutny commented 9 years ago

@llambda I'm going to add some debug logging to spdy. May I ask you to add an env variable and gist the logs after that?

gx0r commented 9 years ago

Yes, sure. By the way, I discovered when I turn off

app.use(require('koa-response-time')());

I no longer get ERR_SPDY_COMPRESSION_ERROR. However Cookies may be getting mangled in requests. I am trying to reproduce in a test case, but no luck yet.

indutny commented 9 years ago

Thank you so much!

Please give a try to spdy@2.0.0-rc2 and set DEBUG="spdy:framer:extra" in your environment variables before starting it.

indutny commented 9 years ago

@llambda looks like I still miss a few info :) May ask you to run it again with DEBUG="spdy*"?

gx0r commented 9 years ago

Okay. I updated the gist above.

gx0r commented 9 years ago

Here is another gist. This time reloading the site a few times as the debug output changes.

https://gist.github.com/llambda/dd0cccb3a78f045716a2

indutny commented 9 years ago

Thanks @llambda ! I'll figure it out (probably tomorrow)

gx0r commented 9 years ago

Awesome :smile:

indutny commented 9 years ago

Fixed, it was really stupid: https://github.com/indutny/hpack.js/commit/101622f85193deb8c62a1982900465eec5376abc

indutny commented 9 years ago

Sorry!