Mailing-List: contact bugs-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Apache HTTPD Bugs Notification List" <bugs@httpd.apache.org>
From: bugzilla@apache.org
To: bugs@httpd.apache.org
Subject: DO NOT REPLY [Bug 52476] SSL failures on windows with AcceptFilter
 https none
Date: Wed, 18 Jan 2012 07:47:54 +0000
Message-ID: <bug-52476-7868-5NhGQoi7Pm@https.issues.apache.org/bugzilla/>
In-Reply-To: <bug-52476-7868@https.issues.apache.org/bugzilla/>
References: <bug-52476-7868@https.issues.apache.org/bugzilla/>
Auto-Submitted: auto-generated
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

https://issues.apache.org/bugzilla/show_bug.cgi?id=3D52476

Kaspar Brand <asfbugz@velox.ch> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
         OS/Version|All                         |Windows 7

--- Comment #8 from Kaspar Brand <asfbugz@velox.ch> 2012-01-18 07:47:54 UTC=
 ---
I'm not really familiar with the I/O layer in mod_ssl, unfortunately, but f=
rom
examining the logs provided by Daniel (thanks a lot), there seems to be a
pattern which is common to the failure cases.

In opensslRequest\error.log, we have:

[Tue Jan 17 09:01:00.276626 2012] [ssl:info] [pid 10672:tid 1256] [client
127.0.0.1:55343] AH01964: Connection to child 63 established (server
www.example.com:443)
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace2] [pid 10672:tid 1256]
ssl_engine_rand.c(123): Seeding PRNG with 144 bytes of entropy
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace3] [pid 10672:tid 1256]
ssl_engine_kernel.c(1832): [client 127.0.0.1:55343] OpenSSL: Handshake: sta=
rt
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace3] [pid 10672:tid 1256]
ssl_engine_kernel.c(1840): [client 127.0.0.1:55343] OpenSSL: Loop:
before/accept initialization
[Tue Jan 17 09:01:00.276626 2012] [core:trace6] [pid 10672:tid 1256]
core_filters.c(502): [client 127.0.0.1:55343] core_output_filter: flushing
because of FLUSH bucket
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace4] [pid 10672:tid 1256]
ssl_engine_io.c(2000): [client 127.0.0.1:55343] OpenSSL: I/O error, 11 bytes
expected to read on BIO#2856280 [mem: 28e0888]
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace3] [pid 10672:tid 1256]
ssl_engine_kernel.c(1869): [client 127.0.0.1:55343] OpenSSL: Exit: error in
SSLv2/v3 read client hello A
[Tue Jan 17 09:01:00.276626 2012] [core:trace6] [pid 10672:tid 1256]
core_filters.c(502): [client 127.0.0.1:55343] core_output_filter: flushing
because of FLUSH bucket
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace4] [pid 10672:tid 1256]
ssl_engine_io.c(2000): [client 127.0.0.1:55343] OpenSSL: I/O error, 11 bytes
expected to read on BIO#2856280 [mem: 28e0888]
[Tue Jan 17 09:01:00.276626 2012] [ssl:trace3] [pid 10672:tid 1256]
ssl_engine_kernel.c(1869): [client 127.0.0.1:55343] OpenSSL: Exit: error in
SSLv2/v3 read client hello A

I'm not sure if there's some artifact in the logging infrastructure (all th=
ese
have the same =C2=B5sec timestamp), but what is peculiar is that whenever t=
he
request fails, there are two occurrences of "OpenSSL: I/O error, 11 bytes
expected" - i.e., it looks like the same thread (tid 1256, in the above cas=
e)
is trying to read the client hello, but apparently doesn't get anything.

For successful requests, the 11-byte read succeeds in the first attempt (see
goodRequest\error.log). Finally, in the firefox8.0.1Request\error.log, ther=
e's
this "interesting" combination of events:

[Tue Jan 17 09:03:18.268556 2012] [ssl:info] [pid 1088:tid 1232] [client
127.0.0.1:55354] AH01964: Connection to child 43 established (server
www.example.com:443)
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace2] [pid 1088:tid 1232]
ssl_engine_rand.c(123): Seeding PRNG with 144 bytes of entropy
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace3] [pid 1088:tid 1232]
ssl_engine_kernel.c(1832): [client 127.0.0.1:55354] OpenSSL: Handshake: sta=
rt
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace3] [pid 1088:tid 1232]
ssl_engine_kernel.c(1840): [client 127.0.0.1:55354] OpenSSL: Loop:
before/accept initialization
[Tue Jan 17 09:03:18.268556 2012] [core:trace6] [pid 1088:tid 1232]
core_filters.c(502): [client 127.0.0.1:55354] core_output_filter: flushing
because of FLUSH bucket
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace4] [pid 1088:tid 1232]
ssl_engine_io.c(2000): [client 127.0.0.1:55354] OpenSSL: I/O error, 11 bytes
expected to read on BIO#2756a80 [mem: 27e0890]
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace3] [pid 1088:tid 1232]
ssl_engine_kernel.c(1869): [client 127.0.0.1:55354] OpenSSL: Exit: error in
SSLv2/v3 read client hello A
[Tue Jan 17 09:03:18.268556 2012] [core:trace6] [pid 1088:tid 1232]
core_filters.c(502): [client 127.0.0.1:55354] core_output_filter: flushing
because of FLUSH bucket
[Tue Jan 17 09:03:18.268556 2012] [ssl:trace4] [pid 1088:tid 1232]
ssl_engine_io.c(1989): [client 127.0.0.1:55354] OpenSSL: read 11/11 bytes f=
rom
BIO#2756a80 [mem: 27e0890] (BIO dump follows)

I.e., the first read fails, but the second one succeeds (and again, the
timestamps are identical, but it's unclear if this reflects reality).

--=20
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=3De=
mail
------- You are receiving this mail because: -------
You are the assignee for the bug.=

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