Sorry to be so slow in getting back to you, Joe. I'm still desperately looking for a clue on this SSL "hang" that happens when I run 'apachectl graceful'.
On Wed, 2004-01-14 at 15:51, Joe Orton wrote: > > The client is hanging on a select() call: > > What's the server doing? Hm, I can't seem to figure it out, having bad luck with strace on the server: $ sudo netstat -pt [...] tcp 3066 0 dev37.spdev.colla:https 10.3.0.6:37848 ESTABLISHED 3850/ tcp 4179 0 dev37.spdev.colla:https 10.3.0.6:37786 CLOSE_WAIT 3446/ [...] $ sudo strace -p 3850 trace: ptrace(PTRACE_SYSCALL, ...): Operation not permitted detach: ptrace(PTRACE_DETACH, ...): Operation not permitted $ sudo strace -p 3446 trace: ptrace(PTRACE_SYSCALL, ...): Operation not permitted detach: ptrace(PTRACE_DETACH, ...): Operation not permitted ?? > > > > 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. > > OK, it just looks like the server has hung whilst processing the PUT > request. > > If you apply the attached, graceful won't have the timeout errors which > might ease testing. > I applied the one-lien patch to apache, and still don't see anything particularly telling in either the neon debug log or apache's errorlog. Do you see anything? I still have no more clues about this bug than I did when I first noticed it a week ago. See attached log output.
-------------------------------------------------------------- APACHE ERRORLOG [Tue Jan 20 14:15:06 2004] [info] mod_unique_id: using ip addr 10.1.8.137 [Tue Jan 20 14:15:07 2004] [info] Init: Initializing OpenSSL library [Tue Jan 20 14:15:07 2004] [info] Init: Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [info] Loading certificate & private key of SSL-aware server [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_pphrase.c(497): unencrypted RSA private key - pass phrase not required [Tue Jan 20 14:15:07 2004] [info] Init: Generating temporary RSA private keys (512/1024 bits) [Tue Jan 20 14:15:07 2004] [info] Init: Generating temporary DH parameters (512/1024 bits) [Tue Jan 20 14:15:07 2004] [debug] ssl_scache_dbm.c(437): Inter-Process Session Cache (DBM) Expiry: old: 0, new: 0, removed: 0 [Tue Jan 20 14:15:07 2004] [info] Init: Initializing (virtual) servers for SSL [Tue Jan 20 14:15:07 2004] [info] Configuring server for SSL protocol [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_init.c(436): Creating new SSL context (protocols: SSLv2, SSLv3, TLSv1) [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_init.c(553): Configuring client authentication [Tue Jan 20 14:15:07 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 PROTECTED] [Tue Jan 20 14:15:07 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 PROTECTED] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_init.c(636): Configuring certificate revocation facility [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_init.c(739): Configuring RSA server certificate [Tue Jan 20 14:15:07 2004] [warn] RSA server certificate wildcard CommonName (CN) `*.dev37.spdev.collab.net' does NOT match server name!? [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_init.c(778): Configuring RSA server private key [Tue Jan 20 14:15:07 2004] [info] Server: Apache/2.0.48, Interface: mod_ssl/2.0.48, Library: OpenSSL/0.9.6b [Tue Jan 20 14:15:07 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 [Tue Jan 20 14:15:07 2004] [info] Server built: Jan 7 2004 14:03:58 [Tue Jan 20 14:15:07 2004] [debug] prefork.c(1037): AcceptMutex: sysvsem (default: sysvsem) [Tue Jan 20 14:15:07 2004] [warn] long lost child came home! (pid 3846) [Tue Jan 20 14:15:07 2004] [warn] long lost child came home! (pid 3845) [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#81b81e0 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#8219538 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#8219538 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#8219538 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [info] Connection to child 2 established (server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [info] Seeding PRNG with 136 bytes of entropy [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1778): OpenSSL: Handshake: start [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1786): OpenSSL: Loop: before/accept initialization [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#81b81e0 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 2 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_io.c(1510): OpenSSL: I/O error, 11 bytes expected to read on BIO#8219538 [mem: 823cd20] [Tue Jan 20 14:15:07 2004] [debug] ssl_engine_kernel.c(1815): OpenSSL: Exit: error in SSLv2/v3 read client hello A [Tue Jan 20 14:15:07 2004] [info] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!] [Tue Jan 20 14:15:07 2004] [info] Connection to child 5 closed with abortive shutdown(server dev37.spdev.collab.net:443, client 127.0.0.1) -------------------------------------------------------------- NEON DEBUG OUTPUT (notice: the last request mentioned by neon is a PROPPATCH on 'subverson_logo-384x332.png', but the last action in apache's errorlog has to do with authorizing a PROPPATCH on 'install-sh', which is at least 10 files earlier in the import.) PROPPATCH /svn/cheese/!svn/wrk/5223b166-60d1-0310-b568-9d78d333989a/trunk/importdir/www/subversion_logo-384x332.png 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: 362 Content-Type: text/xml; charset=UTF-8 Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxx Sending request-line and headers: Sending request body... Body block (362 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:mime-type>application/octet-stream</S:mime-type><S:mimetype>image/png</S:mimetype></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: Tue, 20 Jan 2004 22:15:09 GMT Header Name: [date], Value: [Tue, 20 Jan 2004 22:15:09 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] < 213 Got chunk size: 531 Reading 531 bytes of response body. Got 531 bytes. Read block (531 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/5223b166-60d1-0310-b568-9d78d333989a/trunk/importdir/www/subversion_logo-384x332.png</D:href> <D:propstat> <D:prop> <ns1:mime-type/> <ns1:mimetype/> </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 (bin) /home/sussman/projects/1.0-svn/www/favicon.ico Creating request... Running request create hooks. Request created. Running pre_send hooks Sending request headers: PUT /svn/cheese/!svn/wrk/5223b166-60d1-0310-b568-9d78d333989a/trunk/importdir/www/favicon.ico 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: ef5169b040925a716359d131afbea033 Content-Length: 2617 Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxx Sending request-line and headers: Sending request body... Body block (2617 bytes): [SVN] Request body sent: okay. Request sent; retry is 1.
