Welcome! Log In Create A New Profile

Advanced

SSL negotiation failures causing 408 error to be returned

April 15, 2012 11:34PM
While debugging for a client, we found that we're seeing significant numbers of 408s being generated for SSL connections. It seems to be MOSTLY Chrome on a Windows 7 base with some MSIE 9.0 (also on Win 7) as user agents go, and at this point I'm completely stumped. We've tried disabling session cache, upping timeout values, enabling/disabling keepalives, nothing seems to stem the steady flow of these. Below is a sample debug log (I've redacted specific pieces for business reasons). What I see a lot of is 6 simultaneous connections being setup, 2 being used, and then 4 timing out 60s later. Invariably, if I enable full debug, I see 'client timed out (60: Operation timed out) while SSL handshaking' which makes no sense. If I turn on logging for session IDs, I can clearly see the clients being sent 408s are being assigned session IDs which says to me they're completing the SSL negotiation and then just.. sitting idle.

2012/04/14 14:51:41 [debug] 99433#0: *3313 accept: <CLIENT IP> fd:100
2012/04/14 14:51:41 [debug] 99433#0: *3313 post event 0000000801A026F0
2012/04/14 14:51:41 [debug] 99433#0: *3313 delete posted event 0000000801A026F0
2012/04/14 14:51:41 [debug] 99433#0: *3313 malloc: 0000000801EEF000:1256
2012/04/14 14:51:41 [debug] 99433#0: *3313 posix_memalign: 0000000801EE8300:256 @16
2012/04/14 14:51:41 [debug] 99433#0: *3313 malloc: 0000000800DE5000:4096
2012/04/14 14:51:41 [debug] 99433#0: *3313 posix_memalign: 0000000800DFE000:4096 @16
2012/04/14 14:51:41 [debug] 99433#0: *3313 http check ssl handshake
2012/04/14 14:51:41 [debug] 99433#0: *3313 https ssl handshake: 0x16
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL server name: "<SERVER NAME>"
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL_do_handshake: -1
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL_get_error: 2
2012/04/14 14:51:41 [debug] 99433#0: *3313 kevent set event: 100: ft:-1 fl:0025
2012/04/14 14:51:41 [debug] 99433#0: *3313 event timer add: 100: 60000:1334440361120
2012/04/14 14:51:41 [debug] 99433#0: *3313 post event 0000000801A026F0
2012/04/14 14:51:41 [debug] 99433#0: *3313 delete posted event 0000000801A026F0
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL handshake handler: 0
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL_do_handshake: 1
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL: TLSv1, cipher: "RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1"
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL reused session
2012/04/14 14:51:41 [debug] 99433#0: *3313 http process request line
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL_read: -1
2012/04/14 14:51:41 [debug] 99433#0: *3313 SSL_get_error: 2
2012/04/14 14:52:41 [debug] 99433#0: *3313 event timer del: 100: 1334440361120
2012/04/14 14:52:41 [debug] 99433#0: *3313 http process request line
2012/04/14 14:52:41 [info] 99433#0: *3313 client timed out (60: Operation timed out) while SSL handshaking, client: <CLIENT IP>, server:
2012/04/14 14:52:41 [debug] 99433#0: *3313 http request count:1 blk:0
2012/04/14 14:52:41 [debug] 99433#0: *3313 http close request
2012/04/14 14:52:41 [debug] 99433#0: *3313 http log handler
2012/04/14 14:52:41 [debug] 99433#0: *3313 free: 0000000800DFE000, unused: 2426
2012/04/14 14:52:41 [debug] 99433#0: *3313 close http connection: 100
2012/04/14 14:52:41 [debug] 99433#0: *3313 SSL_shutdown: 1
2012/04/14 14:52:41 [debug] 99433#0: *3313 reusable connection: 0
2012/04/14 14:52:41 [debug] 99433#0: *3313 free: 0000000800DE5000
2012/04/14 14:52:41 [debug] 99433#0: *3313 free: 0000000801EEF000
2012/04/14 14:52:41 [debug] 99433#0: *3313 free: 0000000801EE8200, unused: 8
2012/04/14 14:52:41 [debug] 99433#0: *3313 free: 0000000801EE8300, unused: 72

The following 5 UAs are by far the most common

Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.152 Safari/535.19
Mozilla/5.0 (Windows NT 6.1) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19
Mozilla/5.0 (Windows NT 5.1) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19
Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19
Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)

This appears to implicate Windows in some way, but I've yet to figure it out and am, quite frankly, stumped.
Subject Author Posted

SSL negotiation failures causing 408 error to be returned

bpiraeus April 15, 2012 11:34PM

Re: SSL negotiation failures causing 408 error to be returned

bpiraeus April 15, 2012 11:38PM

Re: SSL negotiation failures causing 408 error to be returned

Maxim Dounin April 16, 2012 07:00AM

Re: SSL negotiation failures causing 408 error to be returned

bpiraeus April 16, 2012 10:43AM

Re: SSL negotiation failures causing 408 error to be returned

bpiraeus April 16, 2012 11:14AM

Re: SSL negotiation failures causing 408 error to be returned

Maxim Dounin April 16, 2012 11:26AM

Re: SSL negotiation failures causing 408 error to be returned

bpiraeus April 16, 2012 01:24PM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 259
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready