Unexpectedly large frame. Spdy session is likely corrupt.

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Add the compiled to modules/ directory from apache2
2. Added Loadmodule File to Apache
3. a2enmod spdy && /etc/init.d/apache2 restart
4. Opened a SSL Connection to a specific Vhost. 

What is the expected output? What do you see instead?
I hoped the spdy provided content :) But at least the connection was resetted 
by the server. Log: 
[Tue Jan 24 14:53:45 2012] [warn] [18412:18412:WARNING:spdy_framer.cc(619)] 
Unexpectedly large frame.  Spdy session is likely corrupt.           
[Tue Jan 24 14:53:45 2012] [warn] [18412:18412:WARNING:spdy_framer.cc(773)] 
inflate failure: -3
[Tue Jan 24 14:53:45 2012] [error] [18412:18412:ERROR:spdy_session.cc(147)] 
SpdyFramer error: DECOMPRESS_FAILURE   
[and on and on and on...]

What version of the product are you using? On what operating system?
I checked out the SVN Trunk (at 24th January 2012) and built it on Debian 
Squeeze.

Please provide any additional information below.

I built the module from these How-To's
http://code.google.com/p/mod-spdy/wiki/GettingStarted
http://code.google.com/p/mod-spdy/wiki/HowToBuild

With help from:
http://japhr.blogspot.com/2011/04/dont-bother-with-modspdy.html

Thanks!

Original issue reported on code.google.com by f...@noqqe.de on 24 Jan 2012 at 1:58

[GoogleCodeExporter]

What browser version were you using to load the site?  If it was 
Chrome/Chromium, what is the version number, and what flags was it invoked 
with?  (The easiest thing is to navigate to about:version and paste the 
contents of that page here.)

Original comment by mdste...@google.com on 27 Jan 2012 at 11:09

• Changed state: MoreInfo

[GoogleCodeExporter]

I tried it at first with firefox nightly built (12) and now with chrome:

Google Chrome   16.0.912.77 (Official Build 118311)
OS  Mac OS X
WebKit  535.7 (@105360)
JavaScript  V8 3.6.6.19
Flash   11.1.102.55
User Agent  Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/535.7 
(KHTML, like Gecko) Chrome/16.0.912.77 Safari/535.7
Command Line     /Applications/Google Chrome.app/Contents/MacOS/Google Chrome 
-psn_0_1003765 --flag-switches-begin --enable-print-preview --flag-switches-end
Executable Path /Applications/Google Chrome.app/Contents/MacOS/Google Chrome
Profile Path    /Users/Flo/Library/Application Support/Google/Chrome/Default

Also i tried to force chrome to use spdy with this command:

/Applications/Google\ Chrome.app/Contents/MacOS/Google\ Chrome -psn_0_909534 
--flag-switches-begin --enable-print-preview --flag-switches-end --use-spdy=ssl

But then i get this error in Browser (with my apache module on server side 
(https://spdy.n0q.org):

Error 337 (net::ERR_SPDY_PROTOCOL_ERROR): Unknown error.

at my apache log the entries are:

[Sat Jan 28 13:11:19 2012] [error] [31065:31065:ERROR:mod_spdy.cc(385)] Error 
during speculative read: 20014
[Sat Jan 28 13:11:20 2012] [error] [31072:31072:ERROR:mod_spdy.cc(385)] Error 
during speculative read: 20014
[Sat Jan 28 13:11:58 2012] [error] [30802:30802:ERROR:mod_spdy.cc(385)] Error 
during speculative read: 20014

(differs from my first error)

and at to https://google.com with --use-spdy=ssl i get no site. Its still 
loading (long time)

do you have any idea?

Original comment by f...@noqqe.de on 28 Jan 2012 at 12:18

[GoogleCodeExporter]

Hmm, this is mysterious -- mod_spdy ought to work just fine with that version 
of Chrome (and it has for me, so far).

It's hard for me to diagnose, since I haven't yet been able to reproduce the 
problem.  Some things you could try for now:
- Does using --use-spdy=npn make any difference?
- Does syncing to the most recent revision of mod_spdy make any difference?  
(probably not, but worth a shot)
- Can you tell me what other modules you have installed?  Perhaps mod_spdy is 
interacting badly with one of them.

I'm not surprised that --use-spdy=ssl doesn't work; as I understand it, that 
causes Chrome to ignore NPN, speaking SPDY blindly without first negotiating it 
with the server.

Original comment by mdste...@google.com on 30 Jan 2012 at 9:27

[GoogleCodeExporter]

Hi!

Okay. I built mod_spdy again (as you pleased :))

I started Chrome with: 

/usr/lib/chromium-browser/chromium-browser --flag-switches-begin 
--flag-switches-end --use-spdy=npn

And then i visit my vHost. Chrome(local) said: 

[3038:3057:11485010810:ERROR:x509_certificate_nss.cc(810)] CERT_PKIXVerifyCert 
for spdy.n0q.org failed err=-8179

Think this is not really bad, just because of my selfsigned cert. The Apache 
vHost log said:

[Wed Feb 01 17:44:15 2012] [warn] RSA server certificate CommonName (CN) 
`null.n0q.org' does NOT match server name!?
[Wed Feb 01 17:44:15 2012] [warn] RSA server certificate CommonName (CN) 
`null.n0q.org' does NOT match server name!?
[Wed Feb 01 17:48:27 2012] [error] File does not exist: 
/var/www/spdy.n0q.org/favicon.ico

Looks not bad. The general error.log (since i restarted apache) shows: 

[Wed Feb 01 17:44:15 2012] [warn] Init: Name-based SSL virtual hosts only work 
for clients with TLS server name indication support (RFC 4366)
[Wed Feb 01 17:44:15 2012] [warn] [21322:21322:WARNING:mod_spdy.cc(585)] 
mod_spdy is currently an experimental Apache module. It is not yet suitable for 
production environments and may have stability issues.
[Wed Feb 01 17:44:15 2012] [warn] Init: Name-based SSL virtual hosts only work 
for clients with TLS server name indication support (RFC 4366)
[Wed Feb 01 17:44:15 2012] [notice] Apache/2.2.16 (Debian) mod_ssl/2.2.21 
OpenSSL/1.0.0e configured -- resuming normal operations

Looks good, right? But I took a look at chrome://net-interals and:

"SPDY sessions:
None"

Is this only when i actually hit a session? Or do I have no session because the 
site is acutally loaded?

I created a file about 500 MB to check this:

I went to "Events" in net-internals and Filtered with: "type:SOCKET is:active". 
It only shows me a ssl connection to my spdy vhost. 

Mhpf. What it looks like if a spdy session is active? On server and on client? 
Could you show me some examples?

Original comment by f...@noqqe.de on 1 Feb 2012 at 4:56

[GoogleCodeExporter]

> What it looks like if a spdy session is active? On server and on client? 
Could you show me some examples?

If you're running Chrome with --use-spdy=npn and you connect to a Google https 
site (e.g. https://www.google.com/), you should see e.g. "www.google.com:443" 
listed under "SPDY session:" on the net-internals page (screenshot attached, so 
you'll know exactly what to look for).  If you do see that for 
https://www.google.com/, but _not_ when you connect to your mod_spdy server, 
then something's definitely wrong with mod_spdy.

To verify from the server end if mod_spdy is speaking SPDY to your browser, you 
can set your top-level Apache LogLevel to "notice" (or info or debug) and then 
add the following directive to the top level of your Apache config:

SpdyDebugLoggingVerbosity 1

(or replace 1 with a higher number if you want even more log messages).  With 
that in place, you ought to get messages like this:

[Tue Jan 31 13:21:42 2012] [notice] [client ::1] 
[21631:21631:VERBOSE1:mod_spdy.cc(439)] Starting SPDY session

when a client connects via SPDY.

Sorry this is giving you such trouble.  I'll keep trying to figure out what 
might be wrong.

Original comment by mdste...@google.com on 1 Feb 2012 at 8:31

[GoogleCodeExporter]

Forgot the screenshot, sorry.  Here it is.

Original comment by mdste...@google.com on 1 Feb 2012 at 8:32

Attachments:

• spdy-sessions.png

[GoogleCodeExporter]

mhpf. Yesterday i was sitting for two hours again on my mod_spdy problem. No 
more messages appear in logs of broken spdy sessions. I was pretty annoyed why 
the mod_spdy module doesn't work. So I checked all the steps I took from the 
tutorials again. And than i figured out that I'm such an idiot :) 

I forgot to perform the following step: 

<pre>echo "SpdyEnabled on" | sudo tee /etc/apache2/mods-available/spdy.conf 
</pre>

mod_spdy works now. *Suprise* 

BUT:

It's still strange what appears in my apache log _before_ I added the 
spdy.conf. Why does this messages appear with an disabled mod_spdy?

Kind of strange, isnt it?

Sorry for making such trouble in here... :/ 

Original comment by f...@noqqe.de on 4 Feb 2012 at 12:45

[GoogleCodeExporter]

And once again: Thank you very much for all your help!

Original comment by f...@noqqe.de on 4 Feb 2012 at 12:47

[GoogleCodeExporter]

I suppose we should add a log line to indicate that mod_spdy loaded but was not 
enabled. Matthew what do you think?

Original comment by bmcqu...@google.com on 6 Feb 2012 at 1:33

[GoogleCodeExporter]

Ah, thanks for figuring it out, and glad to hear it's working now!  It 
definitely shouldn't have been breaking things when it wasn't enabled, so 
that's a bug; but it sounds like the problem went away when you updated on Feb 
1, so perhaps it's something that's been fixed in the meantime (possibly by 
r230, which added several additional checks to ensure mod_spdy doesn't do 
anything when it's disabled).  I guess I'll mark this fixed, but do please let 
us know if you have any further issues.

A log message at startup to remind that mod_spdy is disabled sounds like a good 
idea.  (The warning that mod_spdy is still experimental appears whether it is 
enabled or not, and maybe it's time we change that.)  Also, once we're more 
confident that things are stable, I imagine we'll want to change it to being 
enabled by default.

Original comment by mdste...@google.com on 6 Feb 2012 at 4:55

• Changed state: Fixed

[GoogleCodeExporter]

As of r240, mod_spdy now logs a message on startup if it is installed but 
disabled.

Original comment by mdste...@google.com on 7 Feb 2012 at 10:57