serf-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jeff Kaufman <jef...@google.com.INVALID>
Subject Re: Spin when fetching resources over SSL
Date Tue, 27 Oct 2015 20:57:31 GMT
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,  <bert@qqmail.nl> 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: bert@qqmail.nl
> Cc: Jeff Kaufman;dev@serf.apache.org;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,  <bert@qqmail.nl> 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: dev@serf.apache.org
>
>> 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]
>
>>
>
>>
>
>
>
>

Mime
View raw message