SSL Handshake time out
am 09.03.2004 15:38:52 von Joe PearsonThis is a multi-part message in MIME format.
--------------090209090901060905050704
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Transfer-Encoding: 7bit
Hello,
I have a server that has been reaching max clients serveral times per
day. When I look at apache-status, 90% of the children are in "Reading
Request" state. Most of them stay in that state until the apache
"Timeout" is reached. However, some of the children stay reading until I
restart http. Since this causes my server to become unresponsive, I've
lowered the Timeout to 200, which helps somewhat, but we still have the
problem.
Here is server status of a couple of stuck processes:
Srv PID Acc M CPU SS Req Conn Child Slot Client VHost Request
*0-3* 30078 0/2188/2188 *R* 18.95 895 0 0.0 4.30 4.30 ? ?
...reading..
*1-3* 30079 0/2168/2168 *R* 20.22 1 0 0.0 6.59 6.59 ? ?
...reading..
Why do the processes stay "reading" when they have surpassed the
timeout? I've seen other people post about this problem but no one ever
responds.
Here is the ssl log for these "stuck" processes and it usually ends with
"SSL handshake timed out"
[05/Mar/2004 05:52:08 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:08 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:52:08 21978] [trace] Inter-Process Session Cache:
request=GET status=FOUND
id=AABA019681BD42892F8E6F1B30AA9AD295FC1ED0FEEA47F5AB13FB427 087CE5C
(session reuse)
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write finished A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 flush data
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 read finished A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Handshake: done
[05/Mar/2004 05:52:08 21978] [info] Connection: Client IP:
66.153.14.11, Protocol: SSLv3, Cipher: RC4-MD5 (128/128 bits)
[05/Mar/2004 05:52:09 21978] [info] Initial (No.1) HTTPS request
received for child 10 (server www3.homecu.net:443)
[05/Mar/2004 05:52:09 21978] [info] Connection to child 10 closed with
unclean shutdown (server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:12 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:12 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:12 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:12 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write finished A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 flush data
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 read finished A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Handshake: done
[05/Mar/2004 05:52:13 21978] [info] Connection: Client IP:
66.153.14.11, Protocol: SSLv3, Cipher: RC4-MD5 (128/128 bits)
[05/Mar/2004 05:52:13 21978] [info] Initial (No.1) HTTPS request
received for child 10 (server www3.homecu.net:443)
[05/Mar/2004 05:52:13 21978] [info] Connection to child 10 closed with
unclean shutdown (server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:32 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:32 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:32 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:32 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:55:53 21978] [trace] OpenSSL: Exit: error in SSLv2/v3
read client hello A
[05/Mar/2004 05:55:53 21978] [error] SSL handshake timed out (client
66.153.14.11, server www3.homecu.net:443)
This is a redhat 7.2 box with:
openssl-0.9.6b-35.7
mod_ssl-2.8.12-3
apache-1.3.27-3.7.2
Config file SetEnvIf User-Agent ".*MSIE.*" nokeepalive
ssl-unclean-shutdown downgrade-1.0 force-response-1.0
Any ideas where to go from here to determine why this is happening?
Thanks,
Joe Pearson
--------------090209090901060905050704
Content-Type: text/html; charset=us-ascii
Content-Transfer-Encoding: 7bit
Hello,
I have a server that has been reaching max clients serveral times per
day. When I look at apache-status, 90% of the children are in "Reading
Request" state. Most of them stay in that state until the apache
"Timeout" is reached. However, some of the children stay reading until
I restart http. Since this causes my server to become unresponsive,
I've lowered the Timeout to 200, which helps somewhat, but we still
have the problem.
Here is server status of a couple of stuck processes:
Srv | PID | Acc | M | CPU | SS | Req | Conn | Child | Slot | Client | VHost | Request |
---|---|---|---|---|---|---|---|---|---|---|---|---|
0-3 | 30078 | 0/2188/2188 | R | 18.95 | 895 | 0 | 0.0 | 4.30 | 4.30 | ? | ? | ..reading.. |
1-3 | 30079 | 0/2168/2168 | R | 20.22 | 1 | 0 | 0.0 | 6.59 | 6.59 | ? | ? | ..reading.. |
Why do the processes stay "reading" when they have surpassed the
timeout? I've seen other people post about this problem but no one
ever responds.
Here is the ssl log for these "stuck" processes and it usually ends
with "SSL handshake timed out"
[05/Mar/2004 05:52:08 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:08 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:52:08 21978] [trace] Inter-Process Session Cache:
request=GET status=FOUND
id=AABA019681BD42892F8E6F1B30AA9AD295FC1ED0FEEA47F5AB13FB427 087CE5C
(session reuse)
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 write
finished A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 flush data
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Loop: SSLv3 read finished
A
[05/Mar/2004 05:52:08 21978] [trace] OpenSSL: Handshake: done
[05/Mar/2004 05:52:08 21978] [info] Connection: Client IP:
66.153.14.11, Protocol: SSLv3, Cipher: RC4-MD5 (128/128 bits)
[05/Mar/2004 05:52:09 21978] [info] Initial (No.1) HTTPS request
received for child 10 (server www3.homecu.net:443)
[05/Mar/2004 05:52:09 21978] [info] Connection to child 10 closed
with unclean shutdown (server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:12 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:12 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:12 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:12 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 write
finished A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 flush data
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Loop: SSLv3 read finished
A
[05/Mar/2004 05:52:13 21978] [trace] OpenSSL: Handshake: done
[05/Mar/2004 05:52:13 21978] [info] Connection: Client IP:
66.153.14.11, Protocol: SSLv3, Cipher: RC4-MD5 (128/128 bits)
[05/Mar/2004 05:52:13 21978] [info] Initial (No.1) HTTPS request
received for child 10 (server www3.homecu.net:443)
[05/Mar/2004 05:52:13 21978] [info] Connection to child 10 closed
with unclean shutdown (server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:32 21978] [info] Connection to child 10 established
(server www3.homecu.net:443, client 66.153.14.11)
[05/Mar/2004 05:52:32 21978] [info] Seeding PRNG with 1160 bytes of
entropy
[05/Mar/2004 05:52:32 21978] [trace] OpenSSL: Handshake: start
[05/Mar/2004 05:52:32 21978] [trace] OpenSSL: Loop: before/accept
initialization
[05/Mar/2004 05:55:53 21978] [trace] OpenSSL: Exit: error in SSLv2/v3
read client hello A
[05/Mar/2004 05:55:53 21978] [error] SSL handshake timed out (client
66.153.14.11, server www3.homecu.net:443)
This is a redhat 7.2 box with:
openssl-0.9.6b-35.7
mod_ssl-2.8.12-3
apache-1.3.27-3.7.2
Config file SetEnvIf User-Agent ".*MSIE.*" nokeepalive
ssl-unclean-shutdown downgrade-1.0 force-response-1.0
Any ideas where to go from here to determine why this is happening?
Thanks,
Joe Pearson
--------------090209090901060905050704--
____________________________________________________________ __________
Apache Interface to OpenSSL (mod_ssl) www.modssl.org
User Support Mailing List modssl-users@modssl.org
Automated List Manager majordomo@modssl.org