|
Problem with SSL in apache
I am trying to use mod_ssl in apache to authenticate a website service using LDAP. I'm not familiar with SSL errors/log output, so I'm pasting the SSL_ERROR_LOG file below incase someone can help me make sense of this and track down why this is not working correctly...
The machine I am running on is Redhat AS4. Since the log file is so big with sending encrypted keys and whatnot, I've pulled out the information that looks relevent in chronological order. Any assistance on this is greatly appreciated.
[Wed Jan 25 11:46:59 2006] [info] Seeding PRNG with 136 bytes of entropy
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1771): OpenSSL: Handshake: start
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: before/accept initialization
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 11/11 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(716): inside shmcb_retrieve_session
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(728): id[0]=34, masked index=2
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(1191): entering shmcb_lookup_session_id
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(979): entering shmcb_expire_division
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(1201): loop=0, count=1, curr_pos=0
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(1205): idx->s_id2=66, id[1]=66, offset=0
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(1222): at index 0, found possible session match
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(1241): a match!
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(744): leaving shmcb_retrieve_session
[Wed Jan 25 11:46:59 2006] [debug] ssl_scache_shmcb.c(425): shmcb_retrieve had a hit
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1617): Inter-Process Session Cache: request=GET status=FOUND
id=224297FC845276A64690B290920AA40D84B3247ED014EF84C2C2429856A05EAD (session reuse)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read client hello A
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write server hello A
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write change cipher spec A
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write finished A
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 flush data
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read finished A
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_kernel.c(1775): OpenSSL: Handshake: done
[Wed Jan 25 11:46:59 2006] [info] Connection: Client IP: 10.1.1.112, Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA
(256/256 bits)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1478): | 0000: 17 03 01 02 30
....0 ----+
[Wed Jan 25 11:46:59 2006] [info] Initial (No.1) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1478): | 0000: 17 03 01 02
.... |
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1482): | 0005 - <SPACES/NULS>
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1484):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 544/544 bytes from BIO#8cacd98 [mem: 92f6c0d]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [info] Subsequent (No.2) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1484):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [info] Subsequent (No.3) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:46:59 2006] [info] Subsequent (No.4) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:46:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#91ed100 [mem: 9291930]
(BIO dump follows)
--------------+
[Wed Jan 25 11:46:59 2006] [info] Subsequent (No.8) HTTPS request received for child 0 (server my.server.org:443)
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1478): | 0000: 17 03 01 02
.... |
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1482): | 0005 - <SPACES/NULS>
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1484):
+-------------------------------------------------------------------------+
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:00 2006] [info] Subsequent (No.5) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:47:00 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#91ed100 [mem: 9291930]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:00 2006] [info] Subsequent (No.9) HTTPS request received for child 0 (server my.server.org:443)
[Wed Jan 25 11:47:00 2006] [error] [client 10.1.1.112] File does not exist: /var/www/html/picasso/favicon.ico
[Wed Jan 25 11:47:10 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8cacd98 [mem: 92f6c08]
(BIO dump follows)
[Wed Jan 25 11:47:10 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:11 2006] [info] Subsequent (No.7) HTTPS request received for child 1 (server my.server.org:443)
[Wed Jan 25 11:47:11 2006] [error] [client 10.1.1.112] File does not exist: /var/www/html/picasso/favicon.ico
[Wed Jan 25 11:47:26 2006] [debug] ssl_engine_io.c(1517): OpenSSL: I/O error, 5 bytes expected to read on BIO#91ed100
[mem: 9291930]
[Wed Jan 25 11:47:26 2006] [info] (70007)The timeout specified has expired: SSL input filter read failed.
[Wed Jan 25 11:47:26 2006] [debug] ssl_engine_kernel.c(1789): OpenSSL: Write: SSL negotiation finished successfully
[Wed Jan 25 11:47:26 2006] [info] Connection to child 0 closed with standard shutdown(server my.server.org:443,
client 10.1.1.112)
[Wed Jan 25 11:47:26 2006] [debug] ssl_engine_io.c(1517): OpenSSL: I/O error, 5 bytes expected to read on BIO#8cacd98
[mem: 92f6c08]
[Wed Jan 25 11:47:26 2006] [info] (70007)The timeout specified has expired: SSL library error 1 reading data
[Wed Jan 25 11:47:26 2006] [info] SSL Library Error: 336134278 error:14090086:SSL routines:func(144):reason(134)
[Wed Jan 25 11:47:26 2006] [debug] ssl_engine_kernel.c(1789): OpenSSL: Write: SSL negotiation finished successfully
[Wed Jan 25 11:47:26 2006] [info] Connection to child 1 closed with standard shutdown(server my.server.org:443,
client 10.1.1.112)
[Wed Jan 25 11:47:59 2006] [info] Connection to child 2 established (server my.server.org:443, client 10.1.1.112)
[Wed Jan 25 11:47:59 2006] [info] Seeding PRNG with 136 bytes of entropy
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1771): OpenSSL: Handshake: start
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: before/accept initialization
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 11/11 bytes from BIO#8ddc4c0 [mem: 8e73fb0]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(716): inside shmcb_retrieve_session
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(728): id[0]=34, masked index=2
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(1191): entering shmcb_lookup_session_id
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(979): entering shmcb_expire_division
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(1201): loop=0, count=1, curr_pos=0
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(1205): idx->s_id2=66, id[1]=66, offset=0
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(1222): at index 0, found possible session match
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(1241): a match!
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(744): leaving shmcb_retrieve_session
[Wed Jan 25 11:47:59 2006] [debug] ssl_scache_shmcb.c(425): shmcb_retrieve had a hit
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1617): Inter-Process Session Cache: request=GET status=FOUND
id=224297FC845276A64690B290920AA40D84B3247ED014EF84C2C2429856A05EAD (session reuse)
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read client hello A
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write server hello A
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write change cipher spec A
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write finished A
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 flush data
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8ddc4c0 [mem: 8e73fb0]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read finished A
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_kernel.c(1775): OpenSSL: Handshake: done
[Wed Jan 25 11:47:59 2006] [info] Connection: Client IP: 10.1.1.112, Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA
(256/256 bits)
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8ddc4c0 [mem: 8e73fb0]
(BIO dump follows)
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1478): | 0000: 17 03 01 02 60
....` |
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1484):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 608/608 bytes from BIO#8ddc4c0 [mem: 8e73fb5]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:47:59 2006] [info] Initial (No.1) HTTPS request received for child 2 (server my.server.org:443)
[Wed Jan 25 11:47:59 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8ddc4c0 [mem: 8e73fb0]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:48:00 2006] [info] Subsequent (No.2) HTTPS request received for child 2 (server my.server.org:443)
[Wed Jan 25 11:48:00 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8ddc4c0 [mem: 8e73fb0]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:48:00 2006] [info] Subsequent (No.3) HTTPS request received for child 2 (server my.server.org:443)
[Wed Jan 25 11:48:00 2006] [error] [client 10.1.1.112] File does not exist: /var/www/html/picasso/favicon.ico
[Wed Jan 25 11:48:15 2006] [debug] ssl_engine_io.c(1517): OpenSSL: I/O error, 5 bytes expected to read on BIO#8ddc4c0
[mem: 8e73fb0]
[Wed Jan 25 11:48:15 2006] [info] (70007)The timeout specified has expired: SSL library error 1 reading data
[Wed Jan 25 11:48:15 2006] [info] SSL Library Error: 336134278 error:14090086:SSL routines:func(144):reason(134)
[Wed Jan 25 11:48:15 2006] [debug] ssl_engine_kernel.c(1789): OpenSSL: Write: SSL negotiation finished successfully
[Wed Jan 25 11:48:15 2006] [info] Connection to child 2 closed with standard shutdown(server my.server.org:443,
client 10.1.1.112)
[Wed Jan 25 11:49:38 2006] [info] Connection to child 3 established (server my.server.org:443, client 10.1.1.112)
[Wed Jan 25 11:49:38 2006] [info] Seeding PRNG with 136 bytes of entropy
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1771): OpenSSL: Handshake: start
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: before/accept initialization
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 11/11 bytes from BIO#8bf1748 [mem: 8e9e870]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(716): inside shmcb_retrieve_session
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(728): id[0]=34, masked index=2
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(1191): entering shmcb_lookup_session_id
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(979): entering shmcb_expire_division
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(1201): loop=0, count=1, curr_pos=0
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(1205): idx->s_id2=66, id[1]=66, offset=0
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(1222): at index 0, found possible session match
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(1241): a match!
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(744): leaving shmcb_retrieve_session
[Wed Jan 25 11:49:38 2006] [debug] ssl_scache_shmcb.c(425): shmcb_retrieve had a hit
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1617): Inter-Process Session Cache: request=GET status=FOUND
id=224297FC845276A64690B290920AA40D84B3247ED014EF84C2C2429856A05EAD (session reuse)
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read client hello A
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write server hello A
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write change cipher spec A
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 write finished A
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 flush data
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8bf1748 [mem: 8e9e870]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1779): OpenSSL: Loop: SSLv3 read finished A
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_kernel.c(1775): OpenSSL: Handshake: done
[Wed Jan 25 11:49:38 2006] [info] Connection: Client IP: 10.1.1.112, Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA
(256/256 bits)
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8bf1748 [mem: 8e9e870]
(BIO dump follows)
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1478): | 0000: 17 03 01 02 30
....0 |
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1484):
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 560/560 bytes from BIO#8bf1748 [mem: 8e9e875]
(BIO dump follows)
[Wed Jan 25 11:49:38 2006] [debug] ssl_engine_io.c(1453):
+-------------------------------------------------------------------------+
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:38 2006] [info] Initial (No.1) HTTPS request received for child 3 (server my.server.org:443)
[Wed Jan 25 11:49:39 2006] [debug] ssl_engine_io.c(1506): OpenSSL: read 5/5 bytes from BIO#8bf1748 [mem: 8e9e870]
(BIO dump follows)
+-------------------------------------------------------------------------+
[Wed Jan 25 11:49:39 2006] [info] Subsequent (No.2) HTTPS request received for child 3 (server my.server.org:443)
[Wed Jan 25 11:49:39 2006] [error] [client 10.1.1.112] File does not exist: /var/www/html/picasso/favicon.ico
[Wed Jan 25 11:49:54 2006] [debug] ssl_engine_io.c(1517): OpenSSL: I/O error, 5 bytes expected to read on BIO#8bf1748
[mem: 8e9e870]
[Wed Jan 25 11:49:54 2006] [info] (70007)The timeout specified has expired: SSL input filter read failed.
[Wed Jan 25 11:49:54 2006] [debug] ssl_engine_kernel.c(1789): OpenSSL: Write: SSL negotiation finished successfully
[Wed Jan 25 11:49:54 2006] [info] Connection to child 3 closed with standard shutdown(server my.server.org:443,
client 10.1.1.112)
|
