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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@httpd.apache.org
For additional commands, e-mail: users-h...@httpd.apache.org
