ERROR:mod_spdy.cc(470) Speculative read failed with status 20014: Internal error

[GoogleCodeExporter]

x-mod-spdy:0.9.1.5-301

Server version: Apache/2.2.14 (Ubuntu)
Server built:   Mar  5 2012 16:42:17

Loaded Modules:
 core_module (static)
 log_config_module (static)
 logio_module (static)
 mpm_prefork_module (static)
 http_module (static)
 so_module (static)
 alias_module (shared)
 auth_basic_module (shared)
 authn_file_module (shared)
 authz_default_module (shared)
 authz_groupfile_module (shared)
 authz_host_module (shared)
 authz_user_module (shared)
 autoindex_module (shared)
 cgi_module (shared)
 deflate_module (shared)
 dir_module (shared)
 env_module (shared)
 mime_module (shared)
 evasive20_module (shared)
 negotiation_module (shared)
 php5_module (shared)
 reqtimeout_module (shared)
 setenvif_module (shared)
 spdy_module (shared)
 ssl_module (shared)
 status_module (shared)
Syntax OK

Testing with Windows 7, Google Chrome 18.0.1025.162(Build oficial 131933) m

Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) 
Chrome/18.0.1025.162 Safari/535.19

"chrome.exe" --use-spdy=npn --flag-switches-begin --flag-switches-

What steps will reproduce the problem?
1. Installed mod_spdy (last version)
2. Using RoundCube
3. Start to get strange behavior.
4. Read the logs:

[Tue Apr 17 15:11:31 2012] [notice] child pid 13626 exit signal Segmentation 
fault (11)
[Tue Apr 17 15:11:31 2012] [notice] child pid 13627 exit signal Segmentation 
fault (11)
[Tue Apr 17 15:11:31 2012] [notice] child pid 13628 exit signal Segmentation 
fault (11)
[Tue Apr 17 15:11:50 2012] [error] [client 127.0.0.1] 
[12195:12195:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:07 2012] [error] [client 127.0.0.1] 
[13173:13173:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:23 2012] [error] [client 127.0.0.1] 
[13172:13172:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:24 2012] [error] [client 127.0.0.1] 
[12652:12652:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:25 2012] [error] [client 127.0.0.1] 
[13656:13656:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:26 2012] [error] [client 127.0.0.1] 
[13654:13654:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:27 2012] [error] [client 127.0.0.1] 
[13652:13652:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:28 2012] [error] [client 127.0.0.1] 
[14061:14061:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:29 2012] [error] [client 127.0.0.1] 
[12373:12373:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:30 2012] [error] [client 127.0.0.1] 
[14062:14062:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:32 2012] [error] [client 127.0.0.1] 
[12194:12194:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:33 2012] [error] [client 127.0.0.1] 
[12188:12188:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:35 2012] [error] [client 127.0.0.1] 
[13655:13655:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:49 2012] [error] [client 127.0.0.1] 
[13197:13197:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:50 2012] [error] [client 127.0.0.1] 
[14034:14034:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Tue Apr 17 15:12:51 2012] [error] [client 127.0.0.1] 
[14063:14063:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error

Original issue reported on code.google.com by jor...@gmail.com on 17 Apr 2012 at 9:19

[GoogleCodeExporter]

Same errors here (Linux, fresh spdy install with openssl-1.0.1 and 
apache-2.2.22) :

...... apache error.log ..........

[Thu Apr 19 22:19:05 2012] [error] [client ::1] 
[30814:30814:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Thu Apr 19 22:19:34 2012] [error] [client ::1] 
[30909:30909:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Thu Apr 19 22:19:35 2012] [error] [client ::1] 
[30869:30869:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
[Thu Apr 19 22:19:36 2012] [error] [client ::1] 
[30791:30791:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
........

No access from localhost ([client ::1]) is made, at least apache access.log do 
not reflect it. Enabling debug in logs leads to following :

............ error.log ...........

[Thu Apr 19 22:28:44 2012] [info] [client ::1] Connection to child 14 
established (server xyz.com:443)
[Thu Apr 19 22:28:44 2012] [info] Seeding PRNG with 136 bytes of entropy
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_kernel.c(1866): OpenSSL: 
Handshake: start
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: 
before/accept initialization
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_io.c(1914): OpenSSL: read 11/11 
bytes from BIO#b8264d98 [mem: b826a3a0] (BIO dump follows)
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_io.c(1847): 
+-------------------------------------------------------------------------+
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_io.c(1886): | 0000: 4f 50 54 49 
4f 4e 53 20-2a 20 48                 OPTIONS * H      |
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_io.c(1892): 
+-------------------------------------------------------------------------+
[Thu Apr 19 22:28:44 2012] [debug] ssl_engine_kernel.c(1903): OpenSSL: Exit: 
error in SSLv2/v3 read client hello A
[Thu Apr 19 22:28:44 2012] [info] [client ::1] SSL library error 1 in handshake 
(server xyz.com:443)
[Thu Apr 19 22:28:44 2012] [info] SSL Library Error: 336027900 
error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol speaking 
not SSL to HTTPS port!?
[Thu Apr 19 22:28:44 2012] [info] [client ::1] Connection closed to child 14 
with abortive shutdown (server xyz.com:443)
[Thu Apr 19 22:28:44 2012] [error] [client ::1] 
[31123:31123:ERROR:mod_spdy.cc(470)] Speculative read failed with status 20014: 
Internal error
..............

Original comment by sfinx.so...@gmail.com on 19 Apr 2012 at 7:33

[GoogleCodeExporter]

Also with me,the exact same error, even testing on chrome with https and site 
shows up in SPDY and events as if everything is working, but this error starts 
spinning in the Apache error log.
I couln't figure it out so I switched it off for the time being.

Original comment by whitehaw...@gmail.com on 19 Apr 2012 at 8:27

[GoogleCodeExporter]

Got the gremlin ! :

.... tcpdump -A output on loopback .....
OPTIONS * HTTP/1.0
User-Agent: Apache/2.2.21 (Unix) mod_ssl/2.2.22 OpenSSL/1.0.1 DAV/2 PHP/5.3.8 
(internal dummy connection)
..........................................

Original comment by sfinx.so...@gmail.com on 19 Apr 2012 at 8:44

[GoogleCodeExporter]

Though it is still not clear how to fix or disable it ;(

Original comment by sfinx.so...@gmail.com on 19 Apr 2012 at 8:46

[GoogleCodeExporter]

Ok, seems like this well known apache bug - it use the last "Listen" port for 
plain HTTP dummy connections disregarding the SSL settings. So the easiest way 
is to move "Listen 80" to the end of the httpd.conf - this fixed the issue for 
me ;)

Original comment by sfinx.so...@gmail.com on 19 Apr 2012 at 8:57

[GoogleCodeExporter]

So instead of port 443? Ok I'll give it a shot!

Original comment by whitehaw...@gmail.com on 19 Apr 2012 at 9:04

[GoogleCodeExporter]

Thanks everyone for the detailed reports so far.  I'm trying to sort this out.

The "Speculative read failed" message is logged by mod_spdy whenever an error 
occurs while mod_spdy is trying to initiate the SSL connection to determine 
whether the client wants to use SPDY or not.  It would seem that some internal 
loopback connection is sending an unencrypted OPTIONS request to the SSL port; 
this causes mod_ssl to fail quietly (i.e. at info level), which in turn causes 
mod_spdy to complain (perhaps too) loudly.

If you turn off mod_spdy, but leave the LogLevel at debug, do you still see the 
same messages from mod_ssl?  (Specificially, the "OPTIONS * H" in the BIO dump, 
and the subsequent "speaking not SSL to HTTPS port!?" message)  If so, then 
perhaps this is a benign situation, and mod_spdy simply shouldn't be logging at 
error/warning level.  If not however, then this situation may be a problem that 
mod_spdy is indirectly causing.

Original comment by mdste...@google.com on 19 Apr 2012 at 9:08

[GoogleCodeExporter]

Yes yes , wonderful,sfinx, you got it right! lol I was on this for a couple of 
days on and off. But over here I used the apache 'ports.conf' file instead and 
it worked!
So move the "Listen 80" from near the top past down all 443s all the way to 
bottom. The last line. Restart apache.
The handshake succeeds. lol 

Original comment by whitehaw...@gmail.com on 19 Apr 2012 at 10:46

[GoogleCodeExporter]

Facing the same issue. I can't however use the trick by moving the listen 
statement, it still doesn't work.

The second I disable the spdy module everything is dandy again.

Tell me what to supply to help debug?

/Thomas

Original comment by warpsp...@gmail.com on 21 Apr 2012 at 8:45

[GoogleCodeExporter]

Well you miss something really important in the first post:

[Tue Apr 17 15:11:31 2012] [notice] child pid 13626 exit signal Segmentation 
fault (11)
[Tue Apr 17 15:11:31 2012] [notice] child pid 13627 exit signal Segmentation 
fault (11)
[Tue Apr 17 15:11:31 2012] [notice] child pid 13628 exit signal Segmentation 
fault (11)

I could eliminate the "Speculative read failed" by moving "Listen 80" to the 
end but not the segfaults. This causes the application (here Roundcube and 
phpmyadmin also) not to work any more. Roundcube just does not load any emails 
and reports a server error while phpmyadmin offers the main.php as download. 
The error log shows that the apache child process crashed. "a2dismod spdy" 
solved this ... 

No idea how to debug an apache2 module :(

Original comment by contact....@gmail.com on 21 Apr 2012 at 8:49

[GoogleCodeExporter]

To folks who are getting segfaults:

Can you check if you are using mod_php and the Prefork MPM?  If so, that may be 
the cause of the problem.

mod_spdy is a multithreaded module, very much like the Apache Worker MPM.  PHP 
isn't always thread-safe, so to use PHP with mod_spdy requires configuring your 
server in the same sort of way that one would do so in order to use PHP with 
Apache Worker.  Fortunately, this is usually pretty simple to do.

We've added some documentation on how to do this here: 
https://developers.google.com/speed/spdy/mod_spdy/php
Hopefully, that will fix the issue for you.

If you find that the above does not fix the segfault problem, or if any of you 
are getting segfaults with mod_spdy and are _not_ using mod_php (e.g. you are 
using mod_fcgid instead), please let me know (or add another bug to the 
tracker).

Original comment by mdste...@google.com on 2 May 2012 at 8:08

• Changed state: Accepted

[GoogleCodeExporter]

With regards to the "Speculative read failed", it seems that mod_spdy simply 
shouldn't be logging that condition so noisily.  I will quiet that message in 
the next release so that it doesn't keep spamming the error log.

Original comment by mdste...@google.com on 2 May 2012 at 8:10

[GoogleCodeExporter]

Original comment by mdste...@google.com on 4 May 2012 at 2:53

• Added labels: Milestone-M2

[GoogleCodeExporter]

The noisy "Speculative read failed" messages should be fixed in trunk as of 
r320, so I'm going to go ahead and close this bug.  As mentioned above, if 
after following the instructions at 
https://developers.google.com/speed/spdy/mod_spdy/php you are still seeing 
segfaults when using mod_spdy, please let me know and/or open a new bug.

Original comment by mdste...@google.com on 15 May 2012 at 2:30

• Changed state: Fixed

[GoogleCodeExporter]

I am still getting this message, even with latest mod_spdy. :(

Original comment by ragim...@gmail.com on 23 Jun 2012 at 9:44