mod_ssl/mod_jk failure with client authentication on

Hi,

I apologise for cross-posting - I'm really not sure which component is at
fault, looks like mod_ssl but possibly mod_jk. BTW, is there a list (or some
other venue) dedicated to mod_jk?

My environment is Apache 1.3.22, mod_ssl 2.8.5, OpenSSL 0.9.6b, tomcat 4.0.3.
I have a servlet mounted like this

JkMount /app/servlet/* ajp13
JkMount /app/*.jsp ajp13

SSLVerifyClient require
SSLVerifyDepth 4


When SSLVerifyClient is set to 'none' all works fine, but when I set it as
above, to 'require', it seems that the SSL connection is repetedly
renegotiated. The mod_jk log stop at this line (I edited out log entry
headers for clarity):

Attempting to map URI '/app/servlet/ApplicationProxyServlet'
jk_uri_worker_map_t::map_uri_to_worker, Found a context match ajp13 ->
/app/servlet/

whilst the ssl engine log shows this
Connection to child 3 established (server www-sps.sps.fms.treas.gov:443,
client 164.95.119.43)
Seeding PRNG with 1160 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before/accept initialization
Inter-Process Session Cache: request=GET status=FOUND
id=7A2A7121DDC60F144CA9F233A19E7BD7D88F0DCA06AEB588165EB9F01 CA276DE (session
reuse)
OpenSSL: Loop: SSLv3 read client hello A
OpenSSL: Loop: SSLv3 write server hello A
OpenSSL: Loop: SSLv3 write change cipher spec A
OpenSSL: Loop: SSLv3 write finished A
OpenSSL: Loop: SSLv3 flush data
OpenSSL: Loop: SSLv3 read finished A
OpenSSL: Handshake: done
Connection: Client IP: 164.95.119.43, Protocol: SSLv3, Cipher:
EXP1024-RC4-SHA (56/128 bits)
Initial (No.1) HTTPS request received for child 3 (server
www-sps.sps.fms.treas.gov:443)
OpenSSL: Write: SSL negotiation finished successfully
Connection to child 3 closed with standard shutdown (server
www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
Connection to child 4 established (server www-sps.sps.fms.treas.gov:443,
client 164.95.119.43)
Seeding PRNG with 1160 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before/accept initialization
[Connection to child 5 established (server www-sps.sps.fms.treas.gov:443,
client 164.95.119.43)
Seeding PRNG with 1160 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before/accept initialization
OpenSSL: Loop: SSLv3 read client hello A
OpenSSL: Loop: SSLv3 write server hello A
OpenSSL: Loop: SSLv3 write certificate A
OpenSSL: Loop: SSLv3 write key exchange A
OpenSSL: Loop: SSLv3 write server done A
OpenSSL: Loop: SSLv3 flush data
OpenSSL: Loop: SSLv3 read client key exchange A
OpenSSL: Loop: SSLv3 read finished A
OpenSSL: Loop: SSLv3 write change cipher spec A
OpenSSL: Loop: SSLv3 write finished A
OpenSSL: Loop: SSLv3 flush data
.....


In contrast, when SSLVerifyClient is 'none', mod_jk log shows

Attempting to map URI '/app/servlet/ApplicationProxyServlet'
jk_uri_worker_map_t::map_uri_to_worker, Found a context match ajp13 ->
/app/servlet/
Into wc_get_worker_for_name ajp13
wc_get_worker_for_name, done found a worker
Into jk_worker_t::get_endpoint
In jk_endpoint_t::ajp_get_endpoint, time elapsed since last request = 534
seconds
Into jk_endpoint_t::service
Into ajp_marshal_into_msgb
ajp_marshal_into_msgb - Done
sending to ajp13 #261
ajp_send_request 2: request body to send 4708 - request body to resend 0
sending to ajp13 #4714
received from ajp13 #3
sending to ajp13 #4
received from ajp13 #3
sending to ajp13 #4
received from ajp13 #49
ajp_unmarshal_response: status = 200
ajp_unmarshal_response: Number of headers is = 2
ajp_unmarshal_response: Header[0] [Content-Type] = [application/octet-stream]
ajp_unmarshal_response: Header[1] [Content-Length] = [17776]
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
received from ajp13 #1028
....

and the SSL engine log shows

Connection to child 1 established (server www-sps.sps.fms.treas.gov:443,
client 164.95.119.43)
Seeding PRNG with 1160 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before/accept initialization
OpenSSL: Loop: SSLv3 read client hello A
OpenSSL: Loop: SSLv3 write server hello A
OpenSSL: Loop: SSLv3 write certificate A
OpenSSL: Loop: SSLv3 write key exchange A
OpenSSL: Loop: SSLv3 write server done A
OpenSSL: Loop: SSLv3 flush data
OpenSSL: Loop: SSLv3 read client key exchange A
OpenSSL: Loop: SSLv3 read finished A
OpenSSL: Loop: SSLv3 write change cipher spec A
OpenSSL: Loop: SSLv3 write finished A
OpenSSL: Loop: SSLv3 flush data
Inter-Process Session Cache: request=SET status=OK
id=7D883EF0B18F9E84BC57C4F02C6E34ADF6FF049BB7091F16B303B79AC 906832B
timeout=295s (session caching)
OpenSSL: Handshake: done
Connection: Client IP: 164.95.119.43, Protocol: TLSv1, Cipher:
EDH-RSA-DES-CBC3-SHA (168/168 bits)
Initial (No.1) HTTPS request received for child 1 (server
www-sps.sps.fms.treas.gov:443)
OpenSSL: Write: SSL negotiation finished successfully
Connection to child 1 closed with standard shutdown (server
www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
Connection to child 5 established (server www-sps.sps.fms.treas.gov:443,
client 164.95.119.43)
Seeding PRNG with 1160 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before/accept initialization
Inter-Process Session Cache: request=GET status=FOUND
id=DD717A9F7EB2C33D51E1E33C01CB26E57BFD08D4666799528508521CE 66F4334 (session
reuse)
OpenSSL: Loop: SSLv3 read client hello A
OpenSSL: Loop: SSLv3 write server hello A
OpenSSL: Loop: SSLv3 write change cipher spec A
OpenSSL: Loop: SSLv3 write finished A
OpenSSL: Loop: SSLv3 flush data
OpenSSL: Loop: SSLv3 read finished A
OpenSSL: Handshake: done
Connection: Client IP: 164.95.119.43, Protocol: SSLv3, Cipher:
EXP1024-RC4-SHA (56/128 bits)
Initial (No.1) HTTPS request received for child 5 (server
www-sps.sps.fms.treas.gov:443)

I've spent a couple of days trying to figure this out and have not made any
progress. Can anyone help out? TIA.

-a
--
Aaron Stromas | "Tik-tik-tik!!!... ja, Pantani is weg..."
ams@izoard.com | BRTN commentator
+1 (301) 493 4933 | L'Alpe d'Huez
http://www.izoard.com | 1995 Tour de France

Re: mod_ssl/mod_jk failure with client authentication on

I realised that I included irrelevant log snipet from the SSL log. Please
see the correction below.

Aaron Stromas said:
> Hi,
>
> I apologise for cross-posting - I'm really not sure which component is
> at fault, looks like mod_ssl but possibly mod_jk. BTW, is there a list
> (or some other venue) dedicated to mod_jk?
>
> My environment is Apache 1.3.22, mod_ssl 2.8.5, OpenSSL 0.9.6b, tomcat
> 4.0.3. I have a servlet mounted like this
>
> JkMount /app/servlet/* ajp13
> JkMount /app/*.jsp ajp13
>
> SSLVerifyClient require
> SSLVerifyDepth 4
>
>
> When SSLVerifyClient is set to 'none' all works fine, but when I set it
> as above, to 'require', it seems that the SSL connection is repetedly
> renegotiated. The mod_jk log stop at this line (I edited out log entry
> headers for clarity):
>
> Attempting to map URI '/app/servlet/ApplicationProxyServlet'
> jk_uri_worker_map_t::map_uri_to_worker, Found a context match ajp13 ->
> /app/servlet/
>
> whilst the ssl engine log shows this
> Connection to child 3 established (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Seeding PRNG with 1160 bytes of entropy
> OpenSSL: Handshake: start
> OpenSSL: Loop: before/accept initialization
> Inter-Process Session Cache: request=GET status=FOUND
> id=7A2A7121DDC60F144CA9F233A19E7BD7D88F0DCA06AEB588165EB9F01 CA276DE
> (session reuse)
> OpenSSL: Loop: SSLv3 read client hello A
> OpenSSL: Loop: SSLv3 write server hello A
> OpenSSL: Loop: SSLv3 write change cipher spec A
> OpenSSL: Loop: SSLv3 write finished A
> OpenSSL: Loop: SSLv3 flush data
> OpenSSL: Loop: SSLv3 read finished A
> OpenSSL: Handshake: done
> Connection: Client IP: 164.95.119.43, Protocol: SSLv3, Cipher:
> EXP1024-RC4-SHA (56/128 bits)
> Initial (No.1) HTTPS request received for child 3 (server
> www-sps.sps.fms.treas.gov:443)
> OpenSSL: Write: SSL negotiation finished successfully
> Connection to child 3 closed with standard shutdown (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Connection to child 4 established (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Seeding PRNG with 1160 bytes of entropy
> OpenSSL: Handshake: start
> OpenSSL: Loop: before/accept initialization
> [Connection to child 5 established (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Seeding PRNG with 1160 bytes of entropy
> OpenSSL: Handshake: start
> OpenSSL: Loop: before/accept initialization
> OpenSSL: Loop: SSLv3 read client hello A
> OpenSSL: Loop: SSLv3 write server hello A
> OpenSSL: Loop: SSLv3 write certificate A
> OpenSSL: Loop: SSLv3 write key exchange A
> OpenSSL: Loop: SSLv3 write server done A
> OpenSSL: Loop: SSLv3 flush data
> OpenSSL: Loop: SSLv3 read client key exchange A
> OpenSSL: Loop: SSLv3 read finished A
> OpenSSL: Loop: SSLv3 write change cipher spec A
> OpenSSL: Loop: SSLv3 write finished A
> OpenSSL: Loop: SSLv3 flush data
> ....
[ more SSL handshake]

OpenSSL: Handshake: done
Connection: Client IP: 164.95.119.43, Protocol: TLSv1, Cipher:
EDH-RSA-DES-CBC3-SHA (168/168 bits)
Initial (No.1) HTTPS request received for child 1 (server
www-sps.sps.fms.treas.gov:443)
Changed client verification type will force renegotiation
Requesting connection re-negotiation
Performing full renegotiation: complete handshake protocol
OpenSSL: Write: SSL negotiation finished successfully
Connection to child 0 closed with standard shutdown (server
www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
I/O: sucked 4708 bytes of input data from SSL/TLS I/O layer for delayed
injection into Apache I/O layer
OpenSSL: Handshake: start
OpenSSL: Loop: SSL renegotiate ciphers
OpenSSL: Loop: SSLv3 write hello request A
OpenSSL: Loop: SSLv3 flush data
Awaiting re-negotiation handshake
OpenSSL: Handshake: start
OpenSSL: Loop: before accept initialization
Inter-Process Session Cache: request=REM status=OK
id=38B1D98C2B4A6384FA080BDD4374ACE13881B23AD58834437874A1F03 733FCFE (session
dead)
Write: SSLv3 read client hello B
OpenSSL: Exit: error in SSLv3 read client hello B
Re-negotiation handshake failed: Not accepted by client!?
I/O: injecting 4708 bytes of pre-sucked data into Apache I/O layer
OpenSSL: Write: SSLv3 read client hello B
OpenSSL: Exit: error in SSLv3 read client hello B
SSL error on writing data (OpenSSL library error follows)
OpenSSL: error:140940F5:SSL routines:SSL3_READ_BYTES:unexpected record
Connection to child 1 closed with standard shutdown (server
www-sps.sps.fms.treas.gov:443, client 164.95.119.43)


>
>
> In contrast, when SSLVerifyClient is 'none', mod_jk log shows
>
> Attempting to map URI '/app/servlet/ApplicationProxyServlet'
> jk_uri_worker_map_t::map_uri_to_worker, Found a context match ajp13 ->
> /app/servlet/
> Into wc_get_worker_for_name ajp13
> wc_get_worker_for_name, done found a worker
> Into jk_worker_t::get_endpoint
> In jk_endpoint_t::ajp_get_endpoint, time elapsed since last request =
> 534 seconds
> Into jk_endpoint_t::service
> Into ajp_marshal_into_msgb
> ajp_marshal_into_msgb - Done
> sending to ajp13 #261
> ajp_send_request 2: request body to send 4708 - request body to resend
> 0 sending to ajp13 #4714
> received from ajp13 #3
> sending to ajp13 #4
> received from ajp13 #3
> sending to ajp13 #4
> received from ajp13 #49
> ajp_unmarshal_response: status = 200
> ajp_unmarshal_response: Number of headers is = 2
> ajp_unmarshal_response: Header[0] [Content-Type] =
> [application/octet-stream] ajp_unmarshal_response: Header[1]
> [Content-Length] = [17776]
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> received from ajp13 #1028
> ...
>
> and the SSL engine log shows
>
> Connection to child 1 established (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Seeding PRNG with 1160 bytes of entropy
> OpenSSL: Handshake: start
> OpenSSL: Loop: before/accept initialization
> OpenSSL: Loop: SSLv3 read client hello A
> OpenSSL: Loop: SSLv3 write server hello A
> OpenSSL: Loop: SSLv3 write certificate A
> OpenSSL: Loop: SSLv3 write key exchange A
> OpenSSL: Loop: SSLv3 write server done A
> OpenSSL: Loop: SSLv3 flush data
> OpenSSL: Loop: SSLv3 read client key exchange A
> OpenSSL: Loop: SSLv3 read finished A
> OpenSSL: Loop: SSLv3 write change cipher spec A
> OpenSSL: Loop: SSLv3 write finished A
> OpenSSL: Loop: SSLv3 flush data
> Inter-Process Session Cache: request=SET status=OK
> id=7D883EF0B18F9E84BC57C4F02C6E34ADF6FF049BB7091F16B303B79AC 906832B
> timeout=295s (session caching)
> OpenSSL: Handshake: done
> Connection: Client IP: 164.95.119.43, Protocol: TLSv1, Cipher:
> EDH-RSA-DES-CBC3-SHA (168/168 bits)
> Initial (No.1) HTTPS request received for child 1 (server
> www-sps.sps.fms.treas.gov:443)
> OpenSSL: Write: SSL negotiation finished successfully
> Connection to child 1 closed with standard shutdown (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Connection to child 5 established (server
> www-sps.sps.fms.treas.gov:443, client 164.95.119.43)
> Seeding PRNG with 1160 bytes of entropy
> OpenSSL: Handshake: start
> OpenSSL: Loop: before/accept initialization
> Inter-Process Session Cache: request=GET status=FOUND
> id=DD717A9F7EB2C33D51E1E33C01CB26E57BFD08D4666799528508521CE 66F4334
> (session reuse)
> OpenSSL: Loop: SSLv3 read client hello A
> OpenSSL: Loop: SSLv3 write server hello A
> OpenSSL: Loop: SSLv3 write change cipher spec A
> OpenSSL: Loop: SSLv3 write finished A
> OpenSSL: Loop: SSLv3 flush data
> OpenSSL: Loop: SSLv3 read finished A
> OpenSSL: Handshake: done
> Connection: Client IP: 164.95.119.43, Protocol: SSLv3, Cipher:
> EXP1024-RC4-SHA (56/128 bits)
> Initial (No.1) HTTPS request received for child 5 (server
> www-sps.sps.fms.treas.gov:443)
>
> I've spent a couple of days trying to figure this out and have not made
> any progress. Can anyone help out? TIA.
>
> -a
> --
> Aaron Stromas | "Tik-tik-tik!!!... ja, Pantani is weg..."
> ams@izoard.com | BRTN commentator
> +1 (301) 493 4933 | L'Alpe d'Huez
> http://www.izoard.com | 1995 Tour de France
>
>
>
> ____________________________________________________________ __________
> Apache Interface to OpenSSL (mod_ssl) www.modssl.org
> User Support Mailing List modssl-users@modssl.org
> Automated List Manager majordomo@modssl.org


--
Aaron Stromas | "Tik-tik-tik!!!... ja, Pantani is weg..."
ams@izoard.com | BRTN commentator
+1 (301) 493 4933 | L'Alpe d'Huez
http://www.izoard.com | 1995 Tour de France