httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jens-Uwe Mozdzen <jmozd...@nde.ag>
Subject Re: [users@httpd] SSL session problem
Date Wed, 27 Feb 2013 19:26:01 GMT

Zitat von "Jens-U. Mozdzen" <jmozdzen@nde.ag>:
> Hi list,
>
> I could use a helping hand with a SSL problem. And my excuses for  
> the lengthy message... I've been doing plenty of tests so far, these  
> are my current results...
>
> It's about a web mail site (running Horde5 on SLES11SP2 with latest  
> Novell updates, that's i.e. apache2-2.2.12-1.10.1 and  
> openssl-0.9.8j-0.44.1). Client-side certificates are one of the  
> elements to secure access to the server.
>
> Users reported that sometimes access to the site stalls - one  
> specific case, 100% reproducible in our test environment, is  
> uploading files that exceed a specific size limit.
>
> Symptoms on the client side is that the upload never seems to  
> finish. On the server side, we then see in Apache's error log  
> "Re-negotiation handshake failed: Not accepted by client!?" (and no  
> other errors).
>
> This is *not* the problem of a standard reneg buffer overflow - we  
> have "SSLRenegBufferSize 50486000" in the according <Location>  
> section (and the log message would have been different... been there  
> ;) ).
>
> Generally, access to the https server works nicely, even with the  
> client-side certificates. It are just some very specific "POST  
> request" situations that trigger the symptoms.
>
> As this is perfectly reproducible in our test environment, I've had  
> a look at the trace from both server and client side and can  
> hopefully provide any required details to follow-up questions.
>
> My test case is attaching files to a new email message, which is  
> implemented as an HTML form with POST action. When I attach a file  
> below some limit (3714 bytes) it works, 4480 bytes don't. HTML-wise,  
> the POST contains multiple MIME elements (text email body plus  
> current file attachment), I don't know if it's just that extra size  
> or the multi-part situation - but when I have no body, then larger  
> files work, too.
>
> Client is i.e. Firefox from OpenSUSE (MozillaFirefox-18.0-2.29.2) or  
> via MS Windows (at least version 18.0, if not newer).
>
> I could track things down to the POST request (HTTP content-length:  
> 7795), which (according to the Wireshark traces) simply aborts,  
> meaning the server side seems to just shut down the connection. To  
> limit any side-effects, I restart httpd right before submitting each  
> POST request.
>
> Looking at the traces, what catches the eye is the ordering of the  
> packet flow, which might "contribute to the problem":
>
> client view:
> ... session setup, incl. TLS certificates exchange, session ticket...
> c>s HTTP POST request (7 TCP segments, seq 9909 ack 3993)
> s>c TCP ACK (seq 3393 ack 5773)
> s>c TCP ACK (seq 3393 ack 8513)
> s>c TCP ACK (seq 3393 ack 11253)
> s>c TLSv1 Hello request
> c>s TLSv1 Client Hello
> s>c TCP FIN,ACK (seq 4022 ack 11636)
> c>s TLSv1 Alert (warn/close notify)
> c>s TCP FIN,ACK (seq 11871 ack 4023)
> s>c TCP RST (seq 4022)
> s>c TCP RST (seq 4023)
> s>c TCP RST (seq 4023)
>
> server view:
> ... session setup, incl. TLS certificates exchange, session ticket...
> s>c: TCP ACK (seq 3993 ack 11253)
> c>s: HTTP POST request (7 TCP segments, seq 11253 ack 3993)
> s>c: TLSv1 Hello request
> s>c: TCP FIN,ACK (seq 4022 ack 11636)
> c>s: TLSv1 Client hello
> s>c: TCP RST (seq 4022)
> c>s: TLSv1 Alert (warn/close notify)
> s>c: TCP RST (seq 4023)
> c>s: TCP FIN,ACK (seq 11871 ack 4023)
> s>c: TCP RST (seq 4023)
>
> So the server immediately shuts down the TCP connection after  
> starting the hello sequence, without even giving the client a chance  
> to respond.
>
> When I look at the POST request that works (HTTP content-length:  
> 7042), from the server side it's
> c>s HTTP POST
> s>c TCP ACK
> s>c TLSv1 Hello Request
> c>s TLSv1 Client Hello
> s>c TLSv1 Server Hello
> s>c TLSv1 Certificate request, Server hello done
> ...
> just as one would expect it.
>
> When I set up mod_ssl tracing, I see i.e. the following messages  
> during such an exchange:
>
> --- cut here: error_log.ssl ---
> [Sun Feb 17 17:39:09 2013] [info] Initial (No.1) HTTPS request  
> received for child 0 (server testserver.hh.nde.ag:443)
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(487): [client  
> 192.168.101.26] Changed client verification type will force  
> renegotiation, referer:  
> https://testserver.hh.nde.ag/horde5/imp/dynamic.php?page=compose&type=template&mailbox=SU5CT1gvVGVtcGxhdGVz&uid=4&token=SToMqgkSgG6XH-dspiQTJA1&uniq=1361109712088
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1532): [client  
> 192.168.101.26] filling buffer, max size 50486000 bytes
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1584): [client  
> 192.168.101.26] total of 7813 bytes in buffer, eos=1
> [Sun Feb 17 17:39:09 2013] [info] [client 192.168.101.26] Requesting  
> connection re-negotiation, referer:  
> https://testserver.hh.nde.ag/horde5/imp/dynamic.php?page=compose&type=template&mailbox=SU5CT1gvVGVtcGxhdGVz&uid=4&token=SToMqgkSgG6XH-dspiQTJA1&uniq=1361109712088
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(724): [client  
> 192.168.101.26] Performing full renegotiation: complete handshake  
> protocol, referer:  
> https://testserver.hh.nde.ag/horde5/imp/dynamic.php?page=compose&type=template&mailbox=SU5CT1gvVGVtcGxhdGVz&uid=4&token=SToMqgkSgG6XH-dspiQTJA1&uniq=1361109712088
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1861):  
> OpenSSL: Handshake: start
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1869):  
> OpenSSL: Loop: SSL renegotiate ciphers
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1869):  
> OpenSSL: Loop: SSLv3 write hello request A
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1869):  
> OpenSSL: Loop: SSLv3 flush data
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1869):  
> OpenSSL: Loop: SSLv3 write hello request C
> [Sun Feb 17 17:39:09 2013] [info] [client 192.168.101.26] Awaiting  
> re-negotiation handshake, referer:  
> https://testserver.hh.nde.ag/horde5/imp/dynamic.php?page=compose&type=template&mailbox=SU5CT1gvVGVtcGxhdGVz&uid=4&token=SToMqgkSgG6XH-dspiQTJA1&uniq=1361109712088
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1861):  
> OpenSSL: Handshake: start
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1869):  
> OpenSSL: Loop: before accept initialization
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1886): OpenSSL:  
> I/O error, 5 bytes expected to read on BIO#7fcf89e1ca20 [mem:  
> 7fcf89e220e0]
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_kernel.c(1898):  
> OpenSSL: Exit: error in SSLv3 read client hello B
> [Sun Feb 17 17:39:09 2013] [error] [client 192.168.101.26]  
> Re-negotiation handshake failed: Not accepted by client!?, referer:  
> https://testserver.hh.nde.ag/horde5/imp/dynamic.php?page=compose&type=template&mailbox=SU5CT1gvVGVtcGxhdGVz&uid=4&token=SToMqgkSgG6XH-dspiQTJA1&uniq=1361109712088
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1628): [client  
> 192.168.101.26] read from buffered SSL brigade, mode 0, 8192 bytes
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1703): [client  
> 192.168.101.26] buffered SSL brigade exhausted
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1628): [client  
> 192.168.101.26] read from buffered SSL brigade, mode 0, 8192 bytes
> [Sun Feb 17 17:39:09 2013] [debug] ssl_engine_io.c(1628): [client  
> 192.168.101.26] read from buffered SSL brigade, mode 2, 0 bytes
> --- cut here ---
>
> Somehow, it again seems, that the server isn't "waiting" for the  
> client's "TLS Client Hello" but immediately aborts (OpenSSL: I/O  
> error, 5 bytes expected to read on BIO#7fcf89e1ca20).
>
> Since everything else works, including accessing the  
> certificate-protected areas of the server (and I see the completed  
> initial negotiation of the TLS session including the certificates),  
> I'm lost. Can somebody give me a helping hand on how to find the  
> root cause of this?
>
> With regards,
> Jens

I re-tested the environment with an updated client system (firefox 19,  
openssl 1.0.1e), same results.

In parallel, we've set up a different apache environment on the same  
SLES11SP2 server:

www:/opt/lampp # bin/httpd -V
Server version: Apache/2.4.3 (Unix)
Server built:   Aug 28 2012 06:58:02
Server's Module Magic Number: 20120211:6
Server loaded:  APR 1.4.6, APR-UTIL 1.4.1
Compiled using: APR 1.4.6, APR-UTIL 1.4.1

and openssl 1.0.1c - and that software combo works like a charm. So I  
believe I can say it's not client-specific, but a software problem on  
the server side.

As production servers are affected, I'd like to know whether the root  
cause lies within openssl or within Apache's mod_ssl, so I can ask the  
distribution folks to update appropriately.

Any help out there?

Regards,
Jens
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
> For additional commands, e-mail: users-help@httpd.apache.org


-- 
Jens-U. Mozdzen                         voice   : +49-40-559 51 75
NDE Netzdesign und -entwicklung AG      fax     : +49-40-559 51 77
Postfach 61 03 15                       mobile  : +49-179-4 98 21 98
D-22423 Hamburg                         e-mail  : jmozdzen@nde.ag

         Vorsitzende des Aufsichtsrates: Angelika Mozdzen
           Sitz und Registergericht: Hamburg, HRB 90934
                   Vorstand: Jens-U. Mozdzen
                    USt-IdNr. DE 814 013 983


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org


Mime
View raw message