Subject: mod_ssl/mod_jk failure with client authentication on

From: "Aaron Stromas" <[email-masked]>
Date: Fri, 7 Mar 2003 08:19:55 -0500 (EST)

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
<Location "/app/">
        SSLVerifyClient require
        SSLVerifyDepth  4
</Location>

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=7A2A7121DDC60F144CA9F233A19E7BD7D88F0DCA06AEB588165EB9F01CA276DE (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=7D883EF0B18F9E84BC57C4F02C6E34ADF6FF049BB7091F16B303B79AC906832B
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=DD717A9F7EB2C33D51E1E33C01CB26E57BFD08D4666799528508521CE66F4334 (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..."
[email-masked]        | 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                      [email-masked]
Automated List Manager                            [email-masked]

---

From: "Aaron Stromas" <[email-masked]>
Date: Fri, 7 Mar 2003 08:55:32 -0500 (EST)

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
>
> 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
> Connection to child 3 established (server
> id=7A2A7121DDC60F144CA9F233A19E7BD7D88F0DCA06AEB588165EB9F01CA276DE
> (session reuse)
> Connection to child 4 established (server
> [Connection to child 5 established (server
  [ 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=38B1D98C2B4A6384FA080BDD4374ACE13881B23AD58834437874A1F03733FCFE (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 jk_endpoint_t::ajp_get_endpoint, time elapsed since last request =
> 534 seconds
> 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: Header[0] [Content-Type] =
> [application/octet-stream] ajp_unmarshal_response: Header[1]
> [Content-Length] = [17776]
> Connection to child 1 established (server
> Connection to child 5 established (server
> id=DD717A9F7EB2C33D51E1E33C01CB26E57BFD08D4666799528508521CE66F4334
> (session reuse)
> I've spent a couple of days trying to figure this out and have not made
> any progress. Can anyone help out? TIA.
>
> -a
> --