httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ben Collins-Sussman <suss...@collab.net>
Subject Re: SSL renegotiation bug
Date Wed, 14 Jan 2004 21:27:23 GMT
On Tue, 2004-01-13 at 17:26, Joe Orton wrote:

> Is there still a TCP connection between the client and server at this
> point?  If so, you can identify the server child in question via the
> server-status output or "netstat -pt", and strace the process to see
> what it's doing.

After the hang, 'netstat -pt' on both client and server systems shows
an ESTABLISHED connection:

   (client):  
tcp        0  0 10.3.0.6:34027   10.1.8.137:https  ESTABLISHED 17769/svn

   (server):
tcp    10055  0 dev37.spdev.colla:https 10.3.0.6:34027 ESTABLISHED 3772/


The client is hanging on a select() call:

$ strace -p 17769
select(4, [3], NULL, NULL, {999869, 310000}


> If you re-order the Listen statements in your httpd.conf so "Listen 443"
> is before "Listen 80", then the dummy connections should hit the port 80
> vhost instead, and remove the spam.

Done.  No more 'dummy connection' spam in errorlog.

>   So I'd retry like that and see if the error log output is more useful. 

See bottom of this mail.  I see only one [error] message among the
[debug] messages, something about "waited for children for more than 8s
in graceful restart; exiting the loop".

>  The neon debug log output might also help.

Okay, I set neon-debug-mask=130, and attached the last output leading up
to the hang.  See below.



--------------------------------------
APACHE ERRORLOG

[Wed Jan 14 13:22:52 2004] [debug] mpm_common.c(521): (70007)The timeout
specified has expired: connect to listener
[Wed Jan 14 13:22:52 2004] [info] mod_unique_id: using ip addr
10.1.8.137
[Wed Jan 14 13:22:52 2004] [info] Init: Initializing OpenSSL library
[Wed Jan 14 13:22:52 2004] [info] Init: Seeding PRNG with 136 bytes of
entropy
[Wed Jan 14 13:22:52 2004] [info] Loading certificate & private key of
SSL-aware server
[Wed Jan 14 13:22:52 2004] [debug] ssl_engine_pphrase.c(497):
unencrypted RSA private key - pass phrase not required
[Wed Jan 14 13:22:52 2004] [info] Init: Generating temporary RSA private
keys (512/1024 bits)
[Wed Jan 14 13:22:53 2004] [info] Init: Generating temporary DH
parameters (512/1024 bits)
[Wed Jan 14 13:22:53 2004] [info] Init: Initializing (virtual) servers
for SSL
[Wed Jan 14 13:22:53 2004] [info] Configuring server for SSL protocol
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(436): Creating new
SSL context (protocols: SSLv2, SSLv3, TLSv1)
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(553): Configuring
client authentication
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(1104): CA
certificate: /C=US/ST=California/L=Brisbane/O=CollabNet,
Inc./OU=Engineering/CN=CollabNet Test Certificate\ Authority - FOR
TESTING ONLY/Email=security@collab.net
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(1104): CA
certificate: /C=US/ST=California/L=Brisbane/O=CollabNet,
Inc./OU=Engineering/CN=CollabNet Test Certificate\ Authority - FOR
TESTING ONLY/Email=security@collab.net
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(636): Configuring
certificate revocation facility
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(739): Configuring
RSA server certificate
[Wed Jan 14 13:22:53 2004] [warn] RSA server certificate wildcard
CommonName (CN) `*.dev37.spdev.collab.net' does NOT match server name!?
[Wed Jan 14 13:22:53 2004] [debug] ssl_engine_init.c(778): Configuring
RSA server private key
[Wed Jan 14 13:22:53 2004] [info] Server: Apache/2.0.48, Interface:
mod_ssl/2.0.48, Library: OpenSSL/0.9.6b
[Wed Jan 14 13:22:53 2004] [notice] Apache/2.0.48 (Unix) mod_ssl/2.0.48
OpenSSL/0.9.6b DAV/2 mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1
mod_auth_svn/0.1 AuthMySQL/2.20 con\figured -- resuming normal
operations
[Wed Jan 14 13:22:53 2004] [info] Server built: Jan  7 2004 14:03:58
[Wed Jan 14 13:22:53 2004] [debug] prefork.c(1037): AcceptMutex: sysvsem
(default: sysvsem)
[Wed Jan 14 13:22:53 2004] [warn] long lost child came home! (pid 6562)
[Wed Jan 14 13:22:53 2004] [warn] long lost child came home! (pid 6561)

-----------------------------------------------
NEON DEBUG OUTPUT


Creating request...
Running request create hooks.
Request created.
Running pre_send hooks
Sending request headers:
PUT
/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h
HTTP/1.1
Host: cheese.dev37.spdev.collab.net
User-Agent: SVN/0.36.0 (dev build) neon/0.24.4
Connection: TE
TE: trailers
Content-Type: application/vnd.svn-svndiff
X-SVN-Result-Fulltext-MD5: 9186656d79f754e34065f8ce66fe816f
Content-Length: 866
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Sending request body...
Body block (866 bytes):
[SVN]
Request body sent: okay.
Request sent; retry is 1.
[status-line] < HTTP/1.1 201 Created
[hdr] Date: Wed, 14 Jan 2004 21:22:58 GMT
Header Name: [date], Value: [Wed, 14 Jan 2004 21:22:58 GMT]
[hdr] Server: Apache/2.0.48 (Unix) mod_ssl/2.0.48 OpenSSL/0.9.6b DAV/2
mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1 mod_auth_svn/0.1 AuthMySQL/2.20
Header Name: [server], Value: [Apache/2.0.48 (Unix) mod_ssl/2.0.48
OpenSSL/0.9.6b DAV/2 mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1
mod_auth_svn/0.1 AuthMySQL/2.20]
[hdr] Location:
https://cheese.dev37.spdev.collab.net/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h
Header Name: [location], Value:
[https://cheese.dev37.spdev.collab.net/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h]
[hdr] Content-Length: 503
Header Name: [content-length], Value: [503]
[hdr] Content-Type: text/html
Header Name: [content-type], Value: [text/html]
[hdr] 
End of headers.
Reading 503 bytes of response body.
Got 503 bytes.
Read block (503 bytes):
[<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>201 Created</title>
</head><body>
<h1>Created</h1>
<p>Resource
/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h
has been created.</p>
<hr />
<address>Apache/2.0.48 (Unix) mod_ssl/2.0.48 OpenSSL/0.9.6b DAV/2
mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1 mod_auth_svn/0.1 AuthMySQL/2.20
Server at cheese.dev37.spdev.collab.net Port 443</address>
</body></html>
]
Running post_send hooks
Request ends, status 201 class 2xx, error line:
201 Created
Running destroy hooks.
Request ends.
Creating request...
Running request create hooks.
Request created.
Running pre_send hooks
Sending request headers:
PROPPATCH
/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h
HTTP/1.1
Host: cheese.dev37.spdev.collab.net
User-Agent: SVN/0.36.0 (dev build) neon/0.24.4
Connection: TE
TE: trailers
Content-Length: 310
Content-Type: text/xml; charset=UTF-8
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Sending request body...
Body block (310 bytes):
[<?xml version="1.0" encoding="utf-8" ?>
<D:propertyupdate xmlns:D="DAV:"
xmlns:V="http://subversion.tigris.org/xmlns/dav/"
xmlns:C="http://subversion.tigris.org/xmlns/custom/"
xmlns:S="http://subversion.tigris.org/xmlns/svn/"><D:set><D:prop><S:eol-style>native</S:eol-style></D:prop></D:set></D:propertyupdate>]
Request body sent: okay.
Request sent; retry is 1.
[status-line] < HTTP/1.1 207 Multi-Status
[hdr] Date: Wed, 14 Jan 2004 21:22:58 GMT
Header Name: [date], Value: [Wed, 14 Jan 2004 21:22:58 GMT]
[hdr] Server: Apache/2.0.48 (Unix) mod_ssl/2.0.48 OpenSSL/0.9.6b DAV/2
mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1 mod_auth_svn/0.1 AuthMySQL/2.20
Header Name: [server], Value: [Apache/2.0.48 (Unix) mod_ssl/2.0.48
OpenSSL/0.9.6b DAV/2 mod_auth_mda/2.0 mod_jk/1.2.0 SVN/0.35.1
mod_auth_svn/0.1 AuthMySQL/2.20]
[hdr] Transfer-Encoding: chunked
Header Name: [transfer-encoding], Value: [chunked]
[hdr] Content-Type: text/xml; charset="utf-8"
Header Name: [content-type], Value: [text/xml; charset="utf-8"]
[hdr] 
End of headers.
New chunk.
[Chunk Size] < 217
Got chunk size: 535
Reading 535 bytes of response body.
Got 535 bytes.
Read block (535 bytes):
[<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:"
xmlns:ns3="http://subversion.tigris.org/xmlns/dav/"
xmlns:ns2="http://subversion.tigris.org/xmlns/custom/"
xmlns:ns1="http://subversion.tigris.org/xmlns/svn/" xmlns:ns0="DAV:">
<D:response>
<D:href>/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/JNIByteArray.h</D:href>
<D:propstat>
<D:prop>
<ns1:eol-style/>
</D:prop>
<D:status>HTTP/1.1 200 OK</D:status>
</D:propstat>
</D:response>
</D:multistatus>
]
New chunk.
[Chunk Size] < 0
Got chunk size: 0
Zero-size chunk.
[hdr] 
End of headers.
Running post_send hooks
Request ends, status 207 class 2xx, error line:
207 Multi-Status
Running destroy hooks.
Request ends.
Adding        
/home/sussman/projects/1.0-svn/subversion/bindings/java/javahl/native/Prompter.cpp
Creating request...
Running request create hooks.
Request created.
Running pre_send hooks
Sending request headers:
PUT
/svn/cheese/!svn/wrk/bfe853f3-e6d0-0310-ba3f-902a2f8ae0b5/trunk/svncode2/subversion/bindings/java/javahl/native/Prompter.cpp
HTTP/1.1
Host: cheese.dev37.spdev.collab.net
User-Agent: SVN/0.36.0 (dev build) neon/0.24.4
Connection: TE
TE: trailers
Content-Type: application/vnd.svn-svndiff
X-SVN-Result-Fulltext-MD5: c39198629f8558b630e9f103d6bdc1a6
Content-Length: 3808
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Sending request body...
Body block (3808 bytes):
[SVN]
Request body sent: okay.
Request sent; retry is 1.



Mime
View raw message