I just rebuilt against trunk at r1710846 and ran into this again: 2015-10-27T16:52:31.589023-04 DEBUG [l:2620:0:1004:2:6c57:4dc:8e89:3aea:53729 r:2607:f8b0:4006:80e::2004:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: ssl_decrypt: begin 8000 2015-10-27T16:52:31.589029-04 DEBUG [l:2620:0:1004:2:6c57:4dc:8e89:3aea:53729 r:2607:f8b0:4006:80e::2004:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: bio_bucket_read called for 5 bytes 2015-10-27T16:52:31.589043-04 DEBUG [l:2620:0:1004:2:6c57:4dc:8e89:3aea:53729 r:2607:f8b0:4006:80e::2004:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: SSL_connect:read error in SSLv3 read server session ticket A: ssl_error=2, status=11 2015-10-27T16:52:31.589048-04 DEBUG [l:2620:0:1004:2:6c57:4dc:8e89:3aea:53729 r:2607:f8b0:4006:80e::2004:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: ssl_decrypt: 11 0
I was curious if this might be ipv6 related, but after disabling ipv6 I got the same problem: 2015-10-27T16:55:51.974660-04 DEBUG [l:172.29.73.76:57202 r:216.58.219.228:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: ssl_decrypt: begin 8000 2015-10-27T16:55:51.974667-04 DEBUG [l:172.29.73.76:57202 r:216.58.219.228:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: bio_bucket_read called for 5 bytes 2015-10-27T16:55:51.974679-04 DEBUG [l:172.29.73.76:57202 r:216.58.219.228:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: SSL_connect:read error in SSLv3 read server session ticket A: ssl_error=2, status=11 2015-10-27T16:55:51.974684-04 DEBUG [l:172.29.73.76:57202 r:216.58.219.228:443] third_party/instaweb/src/third_party/serf/instaweb_ssl_buckets.c: ssl_decrypt: 11 0 It still just loops here printing the same messages over and over until timeout. On Sat, Oct 24, 2015 at 5:40 AM, <[email protected]> wrote: > Wild guess: could this be related to certificate checking or something? > > > > Just a few days ago I had a problem connecting to https://twitter.com, using > trunk in a specific http/2 related mode. > > > > After quite a bit of printf style debugging (and then partially removing > that as it affected timing) I found that Serf sometimes tried to perform > socket operations (such as reading) on a not yet connected socket. On > Windows this returns a specific error, but I could imagine that a not > connected socket might have other problems on other platforms. > > (And the faster your CPU, the more likely you see this problem... as in > general the ssl engine needs to initialize within this timeframe too) > > > > I solved this problem on trunk, but if not really necessay I'd rather not > backport this fix as it affects timing on quite a bit of initialization > code... which might trigger bugs in other code that relies on something > without knowing. > > > > Bert > > > > Sent from Mail for Windows 10 > > > > > > > From: Jeff Kaufman > Sent: vrijdag 23 oktober 2015 15:17 > To: [email protected] > Cc: Jeff Kaufman;[email protected];Jeffrey Crowell;Maksim Orlovich > Subject: Re: Spin when fetching resources over SSL > > > > > > Yes 70014 is APR_EOF on my platform too. > > > > It's weird that we're spinning, but it's also weird we're getting EOF > > early in the process when setting up an ssl connection, no? (Every > > time, every ssl server, not just occasionally.) > > > > I'll check out the 1.3.x branch. > > > > On Fri, Oct 23, 2015 at 9:07 AM, <[email protected]> wrote: > >> If your error codes are the same as on my platform (I'm on Windows) 70014 >> stands for APR_EOF. In that case it shouldn't loop further. > >> > >> The logs you provide don't have anything else that stands out for me. If >> you can post the full log on some url I'm willing to check if I see >> something else. > >> > >> You might want to check the 1.3.x branch as it has some further fixes we >> hope to release 'soon'. > >> > >> Trunk is a bit further away from release, but contains even more ssl code >> cleanups. Test input on that codebase is very welcome. (Please ignore the >> current HTTP/2 work for now. That is currently unexposed in the higher >> layers) > >> > >> Bert > >> > >> Sent from Mail for Windows 10 > >> > >> > >> > >> From: Jeff Kaufman > >> Sent: donderdag 22 oktober 2015 19:23 > >> To: [email protected] > >> Cc: Jeffrey Crowell;Maksim Orlovich > >> Subject: Spin when fetching resources over SSL > >> > >> > >> The mod_pagespeed project uses serf for fetching, and I'm currently > >> updating our dependency from 1.1.0 to the latest stable, 1.3.8. It > >> works fine for fetching http, but when I try to fetch anything over > >> https it spins in ssl_buckets.c. > >> > >> I turned on verbose logging in serf_private and it seems to be looping in: > >> > >> ssl_buckets.c: ssl_decrypt: begin 8000 > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read waiting: (8 1 9) > >> ssl_buckets.c: bio_bucket_read received 0 bytes (70014) > >> ssl_buckets.c: SSL_connect:error in SSLv3 read server session ticket A > >> ssl_buckets.c: ssl_decrypt: 11 0 9 > >> > >> Have there been any changes to the API since 1.1.0, so that we need to > >> be doing something different to set up ssl with serf? > >> > >> Here's what it prints before going into the spin: > >> > >> outgoing.c: created connection 0x3d6c8638 > >> outgoing.c: created socket for conn 0x3d6c8638, status 0 > >> [l:\200\305\337<\212^?:51912 r:2607:f8b0:4005:801::2004:443] outgoing.c: >> connec\ > >> ted socket for conn 0x3d6c8638, status 115 > >> ssl_buckets.c: ssl_encrypt: begin 8000 > >> ssl_buckets.c: ssl_encrypt: bucket read 96 bytes; status 11 > >> ssl_buckets.c: --- > >> GET / HTTP/1.1^M > >> Host: www.google.com^M > >> User-Agent: Serf/1.3.8 mod_pagespeed/99,99,99,99-99999^M > >> ^M > >> > >> -(96)- > >> ssl_buckets.c: SSL_connect:before connect initialization > >> ssl_buckets.c: bio_bucket_write called for 190 bytes > >> ssl_buckets.c: SSL_connect:SSLv3 write client hello A > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read received 0 bytes (70014) > >> ssl_buckets.c: SSL_connect:error in SSLv3 read server hello A > >> ssl_buckets.c: ssl_encrypt: SSL write: -1 > >> ssl_buckets.c: ssl_encrypt: SSL write error: 2 > >> ssl_buckets.c: ssl_encrypt: SSL write error: 120103 0 > >> ssl_buckets.c: ssl_encrypt read agg: 120103 70014 11 190 > >> ssl_buckets.c: ssl_encrypt finished: 120103 190 (8 1 9) > >> [l::51912 r:2607:f8b0:4005:801::2004:443] outgoing.c: --- socket_sendv: > >> ^V^C^A-(190)- > >> ssl_buckets.c: ssl_decrypt: begin 8000 > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read waiting: (8 1 9) > >> ssl_buckets.c: bio_bucket_read received 0 bytes (70014) > >> ssl_buckets.c: SSL_connect:error in SSLv3 read server hello A > >> [l: ^Q:51912 r:2607:f8b0:4005:801::2004:443] socket_buckets.c: --- >> socket_recv: > >> ^V^C^C > >> -(3505)- > >> ssl_buckets.c: ssl_decrypt: read 3505 bytes (8000); status: 0 > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read waiting: (8 1 9) > >> ssl_buckets.c: bio_bucket_read received 5 bytes (0) > >> ssl_buckets.c: bio_bucket_read called for 67 bytes > >> ssl_buckets.c: bio_bucket_read received 67 bytes (0) > >> ssl_buckets.c: SSL_connect:SSLv3 read server hello A > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read received 5 bytes (0) > >> ssl_buckets.c: bio_bucket_read called for 3081 bytes > >> ssl_buckets.c: bio_bucket_read received 3081 bytes (0) > >> ssl_buckets.c: SSL_connect:SSLv3 read server certificate A > >> ssl_buckets.c: SSL_connect:unknown state > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read received 5 bytes (0) > >> ssl_buckets.c: bio_bucket_read called for 333 bytes > >> ssl_buckets.c: bio_bucket_read received 333 bytes (0) > >> ssl_buckets.c: SSL_connect:SSLv3 read server key exchange A > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read received 5 bytes (0) > >> ssl_buckets.c: bio_bucket_read called for 4 bytes > >> ssl_buckets.c: bio_bucket_read received 4 bytes (70014) > >> ssl_buckets.c: SSL_connect:SSLv3 read server done A > >> ssl_buckets.c: SSL_connect:SSLv3 write client key exchange A > >> ssl_buckets.c: SSL_connect:SSLv3 write change cipher spec A > >> ssl_buckets.c: SSL_connect:SSLv3 write finished A > >> ssl_buckets.c: bio_bucket_write called for 126 bytes > >> ssl_buckets.c: bio_bucket_write waiting: (0 0 0) > >> ssl_buckets.c: SSL_connect:SSLv3 flush data > >> ssl_buckets.c: bio_bucket_read called for 5 bytes > >> ssl_buckets.c: bio_bucket_read received 0 bytes (70014) > >> ssl_buckets.c: SSL_connect:error in SSLv3 read server session ticket A > >> ssl_buckets.c: ssl_decrypt: 11 0 9 > >> > >> [now the block I pulled out above repeats forever] > >> > >> > > > >
