Re: HTTPS connections lock-up with 2.4.18 [SOLVED]

[Yann Ylavic]

On Fri, Feb 5, 2016 at 5:42 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
>
>> Are you sure the earlier sononblock() call succeeded (ie. my patch on
>> socket_bucket_read() does not help)?
>
> It did not get called. The reason was that it assumed the socket was already
> in non-blocking mode. This happened because the build was configured with
> 'ac_cv_o_nonblock_inherited=yes', assuming that this property is inherited
> from the listen socket, but it is not.

Ooook, now it makes sense.

>
> I have to apologize for having wasted your time. I feel really bad about
> this. The only small excuse I have is that we were given the build
> configuration for this cross-compile setup by another company, so in some
> sense we are also a victim ourselves.

No problem, at least we could validate the 2.4.18 changes :)

>
> It doesn't help that the configure script for the apr library silently makes
> the above assumption:
>
>> if test "$cross_compiling" = yes; then :
>>
>> ac_cv_o_nonblock_inherited="yes"
>
>
> This makes it non-obvious that one is creating an incorrect configuration.
> There are several other places in the configure script that make assumptions
> like this. In other places the configure script produces an error instead,
> forcing the user to specify a value, which is much better:
>
>>   if test "$cross_compiling" = yes; then :
>>   as_fn_error $? "cannot check setpgrp when cross compiling" "$LINENO" 5

Cross compiling APR probably needs fixes, patches welcome ;)

>
> Again, sorry about the wasted time.

Thanks for the follow up.

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Stefan Eissing]

FYI: my write lockup is unrelated to yours and resides solely in my own code...

> Am 04.02.2016 um 10:08 schrieb Plüm, Rüdiger, Vodafone Group 
> <ruediger.pl...@vodafone.com>:
> 
> 
> 
>> -Original Message-
>> From: Yann Ylavic [mailto:ylavic@gmail.com]
>> Sent: Donnerstag, 4. Februar 2016 10:04
>> To: httpd-dev
>> Subject: Re: HTTPS connections lock-up with 2.4.18
>> 
>> On Thu, Feb 4, 2016 at 9:54 AM, Yann Ylavic <ylavic@gmail.com> wrote:
>>> On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic <ylavic@gmail.com>
>> wrote:
>>>> Doesn't the socket_bucket_read() call (frame #3) enter
>>>> apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
>>>> socket in O_NONBLOCK?
>>> 
>>> and resets APR_INCOMPLETE_READ.
>> 
>> Would this help?
> 
> As it is easy reproducible in his environment I guess an strace over the 
> whole transaction would be the best approach.
> 
> Regards
> 
> Rüdiger

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

On 2016-02-04 0:54, Yann Ylavic wrote:


On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:

Doesn't the socket_bucket_read() call (frame #3) enter
apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
socket in O_NONBLOCK?


and resets APR_INCOMPLETE_READ.


Yes, it does:

if (t <= 0) {
sock->options &= ~APR_INCOMPLETE_READ;
}

But isn't this precisely the problem? The socket_buffer_read() 
implementation in "srclib/apr/network_io/unix/sendrecv.c" uses select() 
only if the APR_INCOMPLETE_READ flag is SET:


if (sock->options & APR_INCOMPLETE_READ) {
sock->options &= ~APR_INCOMPLETE_READ;
goto do_select;
}

If this flag is clear it goes into the blocking read loop instead:

do {
rv = read(sock->socketdes, buf, (*len));
} while (rv == -1 && errno == EINTR);

How about this small patch:

--- srclib/apr/network_io/unix/sockopt.c.orig	2012-11-07 
08:10:09.0 -0800

+++ srclib/apr/network_io/unix/sockopt.c2016-02-04 14:20:35.755530111 
-0800
@@ -102,7 +102,7 @@
 /* must disable the incomplete read support if we disable
  * a timeout
  */
-if (t <= 0) {
+if (t < 0) {
 sock->options &= ~APR_INCOMPLETE_READ;
 }
 sock->timeout = t;

This seems to get it working, but I'm not sure if there are other 
reasons, not related to blocking versus non-blocking behaviour, for the 
flag to get cleared when timeout is zero.


Thanks,

Joachim

--
joac...@kraut.ca http://www.kraut.ca

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

That previous one-line change was apparently not quite enough. I think I 
still see it occasionally hang, just not all the time. I'm guessing that 
this flag is sometimes already clear on entry to this function, so if we 
want to force a non-blocking read we must explicitly set it:


--- srclib/apr/network_io/unix/sockopt.c.orig	2012-11-07 
08:10:09.0 -0800

+++ srclib/apr/network_io/unix/sockopt.c2016-02-04 15:04:24.833986781 
-0800
@@ -100,11 +100,20 @@
 }
 }
 /* must disable the incomplete read support if we disable
- * a timeout
+ * a timeout...
  */
-if (t <= 0) {
+if (t < 0) {
 sock->options &= ~APR_INCOMPLETE_READ;
 }
+else if (t == 0)
+{
+   /* and must set the APR_INCOMPLETE_READ flag if non-blocking
+* read was requested because apr_socket_recv() does a
+* blocking read if this flag is clear ...
+*/
+   sock->options |= APR_INCOMPLETE_READ;
+}
+
 sock->timeout = t;
 return APR_SUCCESS;
 }

Does the APR_INCOMPLETE_READ flag have another purpose that is 
orthogonal to controlling blocking behaviour? If yes, then I'm a little 
concerned to overload its use like this. Should there be a different 
dedicated flag to control blocking versus non-blocking behaviour? Or is 
the patch safe as is?


Thanks,

Joachim


On 2016-02-04 14:53, Joachim Achtzehnter wrote:

On 2016-02-04 0:54, Yann Ylavic wrote:


On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:

Doesn't the socket_bucket_read() call (frame #3) enter
apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
socket in O_NONBLOCK?


and resets APR_INCOMPLETE_READ.


Yes, it does:

 if (t <= 0) {
 sock->options &= ~APR_INCOMPLETE_READ;
 }

But isn't this precisely the problem? The socket_buffer_read()
implementation in "srclib/apr/network_io/unix/sendrecv.c" uses select()
only if the APR_INCOMPLETE_READ flag is SET:

 if (sock->options & APR_INCOMPLETE_READ) {
 sock->options &= ~APR_INCOMPLETE_READ;
 goto do_select;
 }

If this flag is clear it goes into the blocking read loop instead:

 do {
 rv = read(sock->socketdes, buf, (*len));
 } while (rv == -1 && errno == EINTR);

How about this small patch:

--- srclib/apr/network_io/unix/sockopt.c.orig2012-11-07
08:10:09.0 -0800
+++ srclib/apr/network_io/unix/sockopt.c2016-02-04
14:20:35.755530111 -0800
@@ -102,7 +102,7 @@
  /* must disable the incomplete read support if we disable
   * a timeout
   */
-if (t <= 0) {
+if (t < 0) {
  sock->options &= ~APR_INCOMPLETE_READ;
  }
  sock->timeout = t;

This seems to get it working, but I'm not sure if there are other
reasons, not related to blocking versus non-blocking behaviour, for the
flag to get cleared when timeout is zero.

Thanks,

Joachim



--
joac...@kraut.ca http://www.kraut.ca

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Thu, Feb 4, 2016 at 11:53 PM, Joachim Achtzehnter  wrote:
> On 2016-02-04 0:54, Yann Ylavic wrote:
>
>> On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:
>>>
>>> Doesn't the socket_bucket_read() call (frame #3) enter
>>> apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
>>> socket in O_NONBLOCK?
>>
>>
>> and resets APR_INCOMPLETE_READ.
>
>
> Yes, it does:
>
> if (t <= 0) {
> sock->options &= ~APR_INCOMPLETE_READ;
> }
>
> But isn't this precisely the problem? The socket_buffer_read()
> implementation in "srclib/apr/network_io/unix/sendrecv.c" uses select() only
> if the APR_INCOMPLETE_READ flag is SET:

We don't want to select/poll here (timeout is 0), we want to directly
read non-blocking on the socket.
Since apr_socket_timeout_set(sock, 0)::sononblock() is called (and
succeeds!), recv() should never block (or the system is flawed, or the
socket is in some inconsistent state).
If the timeout were <0, we'd want recv() to block (directly still) and
hence need soblock() before.
If timeout >0, we don't want to wait more than that timeout, so we use
select/poll (timed wait).

>
> How about this small patch:

No, we don't want to poll() before recv() in non-blocking mode, one
system call is enough.

>
> This seems to get it working,

You mean poll()+recv() succeeds? or fails: at poll(), at recv()?
immediatly in any case?
I'm puzzled, why direct non-blocking recv() would block (or not fail)?

Are you sure the earlier sononblock() call succeeded (ie. my patch on
socket_bucket_read() does not help)?

Anyway, I think we need an strace of the process for the whole
connection to figure out the successive syscalls on the socket.

Re: HTTPS connections lock-up with 2.4.18 [SOLVED]

[Joachim Achtzehnter]

Hi Yann,

On 2016-02-04 15:41, Yann Ylavic wrote:

On Thu, Feb 4, 2016 at 11:53 PM, Joachim Achtzehnter  wrote:

On 2016-02-04 0:54, Yann Ylavic wrote:


On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:


Doesn't the socket_bucket_read() call (frame #3) enter
apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
socket in O_NONBLOCK?



and resets APR_INCOMPLETE_READ.



Yes, it does:

 if (t <= 0) {
 sock->options &= ~APR_INCOMPLETE_READ;
 }

But isn't this precisely the problem? The socket_buffer_read()
implementation in "srclib/apr/network_io/unix/sendrecv.c" uses select() only
if the APR_INCOMPLETE_READ flag is SET:


We don't want to select/poll here (timeout is 0), we want to directly
read non-blocking on the socket.


Now I understand. The select() should not be needed for the zero timeout 
case of non-blocking read.



Since apr_socket_timeout_set(sock, 0)::sononblock() is called (and
succeeds!),


Actually, this was not the case. The sononblock() function was never 
called for the accepted sockets. It was called for the listen socket(s), 
but then never again. When I tried to figure out why it was not called I 
eventually discovered the problem, see below.



recv() should never block (or the system is flawed, or the
socket is in some inconsistent state).
If the timeout were <0, we'd want recv() to block (directly still) and
hence need soblock() before.
If timeout >0, we don't want to wait more than that timeout, so we use
select/poll (timed wait).


Right, I get it now.


How about this small patch:


No, we don't want to poll() before recv() in non-blocking mode, one
system call is enough.


Yes


This seems to get it working,


You mean poll()+recv() succeeds? or fails: at poll(), at recv()?
immediatly in any case?
I'm puzzled, why direct non-blocking recv() would block (or not fail)?


It was all working, but for the wrong reasons.


Are you sure the earlier sononblock() call succeeded (ie. my patch on
socket_bucket_read() does not help)?


It did not get called. The reason was that it assumed the socket was 
already in non-blocking mode. This happened because the build was 
configured with 'ac_cv_o_nonblock_inherited=yes', assuming that this 
property is inherited from the listen socket, but it is not.


I have to apologize for having wasted your time. I feel really bad about 
this. The only small excuse I have is that we were given the build 
configuration for this cross-compile setup by another company, so in 
some sense we are also a victim ourselves.


It doesn't help that the configure script for the apr library silently 
makes the above assumption:



if test "$cross_compiling" = yes; then :

ac_cv_o_nonblock_inherited="yes"


This makes it non-obvious that one is creating an incorrect 
configuration. There are several other places in the configure script 
that make assumptions like this. In other places the configure script 
produces an error instead, forcing the user to specify a value, which is 
much better:



  if test "$cross_compiling" = yes; then :
  as_fn_error $? "cannot check setpgrp when cross compiling" "$LINENO" 5


Again, sorry about the wasted time.

Joachim


--
joac...@kraut.ca http://www.kraut.ca

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

> -Original Message-
> From: Yann Ylavic [mailto:ylavic@gmail.com]
> Sent: Donnerstag, 4. Februar 2016 10:04
> To: httpd-dev
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> On Thu, Feb 4, 2016 at 9:54 AM, Yann Ylavic <ylavic@gmail.com> wrote:
> > On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic <ylavic@gmail.com>
> wrote:
> >> Doesn't the socket_bucket_read() call (frame #3) enter
> >> apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
> >> socket in O_NONBLOCK?
> >
> > and resets APR_INCOMPLETE_READ.
> 
> Would this help?

As it is easy reproducible in his environment I guess an strace over the whole 
transaction would be the best approach.

Regards

Rüdiger

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

Doesn't the socket_bucket_read() call (frame #3) enter
apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
socket in O_NONBLOCK?

Maybe "strace" would help here too, since we are in the system now.

On Thu, Feb 4, 2016 at 9:17 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
> Here is the backtrace:
>
>> #0  0xb7fddc40 in __kernel_vsyscall ()
>> #1  0xb7e05f03 in __read_nocancel () at
>> ../sysdeps/unix/syscall-template.S:81
>> #2  0xb7f39589 in apr_socket_recv (sock=sock@entry=0x8156d18,
>> buf=buf@entry=0x8168750 "html, body {\n   font-family: arial,
>> helvetica, sans-serif;\n   font-size: 12px;\n   height: 100%;\n
>> margin:0;\n   padding:0;\n   height:100%;\n}\nbody a, a:hover {\n
>> text-decoration: underline;\n   border:"..., len=len@entry=0xb5e4) at
>> network_io/unix/sendrecv.c:81
>> #3  0xb7f744d5 in socket_bucket_read (a=0x8160fc8, str=0xb5e0,
>> len=0xb5e4, block=APR_NONBLOCK_READ)
>> at buckets/apr_buckets_socket.c:36
>> #4  0x08086a98 in ap_core_input_filter (f=0x8165770, b=0x8165730,
>> mode=AP_MODE_READBYTES, block=APR_NONBLOCK_READ, readbytes=5)
>> at core_filters.c:235
>> #5  0xb7ce732a in bio_filter_in_read (bio=0x81666d8, in=0x816bc83 "",
>> inlen=5)
>> at ssl_engine_io.c:487
>> #6  0xb7b1bc66 in BIO_read ()
>>from /home/joachima/httpd-2.4.18/lib/libcrypto.so.1.0.0
>> #7  0xb7c8e040 in ssl3_read_n ()
>>from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
>> #8  0xb7c8fa75 in ssl3_read_bytes ()
>>from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
>> #9  0xb7c8c211 in ssl3_read ()
>>from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
>> #10 0xb7ca8679 in SSL_read ()
>>from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
>> #11 0xb7ce80d7 in ssl_io_input_read (inctx=inctx@entry=0x81636e8,
>> buf=buf@entry=0x8163710 "GET /css/subpage.css HTTP/1.1\r\nUser-Agent:
>> curl/7.40.0\r\nHost: na171\r\nAccept: */*\r\n\r\n",
>> len=len@entry=0xb8f8)
>> at ssl_engine_io.c:611
>> #12 0xb7cea36c in ssl_io_filter_input (f=0x8165718, bb=0x81660d8,
>> mode=AP_MODE_SPECULATIVE, block=APR_NONBLOCK_READ, readbytes=1)
>> at ssl_engine_io.c:1407
>> #13 0x080a013f in check_pipeline (bb=0x81660d8, c=0x8156eb0)
>> at http_request.c:244
>> #14 ap_process_request_after_handler (r=0x817e2d8) at http_request.c:367
>> #15 0x080a1229 in ap_process_async_request (r=r@entry=0x817e2d8)
>> at http_request.c:448
>> #16 0x080a1575 in ap_process_request (r=r@entry=0x817e2d8)
>> at http_request.c:458
>> #17 0x0809d547 in ap_process_http_sync_connection (c=0x8156eb0)
>> at http_core.c:210
>> #18 ap_process_http_connection (c=0x8156eb0) at http_core.c:251
>> #19 0x0809549d in ap_run_process_connection (c=0x8156eb0) at
>> connection.c:41
>> #20 0x0809589d in ap_process_connection (c=c@entry=0x8156eb0,
>> csd=0x8156d18)
>> at connection.c:213
>> #21 0x080a7849 in child_main (child_num_arg=child_num_arg@entry=0,
>> child_bucket=child_bucket@entry=0) at prefork.c:723
>> #22 0x080a7a9f in make_child (s=0x80f9f38, slot=slot@entry=0,
>> bucket=bucket@entry=0) at prefork.c:767
>> #23 0x080a9091 in prefork_run (_pconf=0x80d50a8, plog=0x80fd9b8,
>> s=0x80f9f38)
>> at prefork.c:979
>> #24 0x08070959 in ap_run_mpm (pconf=pconf@entry=0x80d50a8, plog=0x80fd9b8,
>> s=0x80f9f38) at mpm_common.c:94
>> #25 0x08069f23 in main (argc=4, argv=0xbd54) at main.c:777
>
>
>
> On 2016-02-03 11:50 PM, Plüm, Rüdiger, Vodafone Group wrote:
>
>> Can you also post the backtrace when the server is hanging in the read?
>>
>> Regards
>>
>> Rüdiger
>>
>>> -Original Message-
>>> From: Plüm, Rüdiger, Vodafone Group
>>> Sent: Donnerstag, 4. Februar 2016 08:39
>>> To: dev@httpd.apache.org
>>> Subject: RE: HTTPS connections lock-up with 2.4.18
>>>
>>> Thanks. Which version of APR / APR-UTIL are you using?
>>>
>>> Regards
>>>
>>> Rüdiger
>>>
>>>> -Original Message-
>>>> From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
>>>> Sent: Donnerstag, 4. Februar 2016 03:56
>>>> To: dev@httpd.apache.org
>>>> Subject: Re: HTTPS connections lock-up with 2.4.18
>>>>
>>>> Perhaps, there is an important clue this time. When I retrieve a file
>>>> that works we see the following log messages near the time when the
>>>> reply is being written:
>>>>

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:
> Doesn't the socket_bucket_read() call (frame #3) enter
> apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
> socket in O_NONBLOCK?

and resets APR_INCOMPLETE_READ.

>
> Maybe "strace" would help here too, since we are in the system now.
>

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

Here is the backtrace:


#0  0xb7fddc40 in __kernel_vsyscall ()
#1  0xb7e05f03 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:81
#2  0xb7f39589 in apr_socket_recv (sock=sock@entry=0x8156d18,
buf=buf@entry=0x8168750 "html, body {\n   font-family: arial, helvetica, 
sans-serif;\n   font-size: 12px;\n   height: 100%;\n   margin:0;\n   padding:0;\n   
height:100%;\n}\nbody a, a:hover {\n   text-decoration: underline;\n   border:"..., 
len=len@entry=0xb5e4) at network_io/unix/sendrecv.c:81
#3  0xb7f744d5 in socket_bucket_read (a=0x8160fc8, str=0xb5e0,
len=0xb5e4, block=APR_NONBLOCK_READ)
at buckets/apr_buckets_socket.c:36
#4  0x08086a98 in ap_core_input_filter (f=0x8165770, b=0x8165730,
mode=AP_MODE_READBYTES, block=APR_NONBLOCK_READ, readbytes=5)
at core_filters.c:235
#5  0xb7ce732a in bio_filter_in_read (bio=0x81666d8, in=0x816bc83 "", inlen=5)
at ssl_engine_io.c:487
#6  0xb7b1bc66 in BIO_read ()
   from /home/joachima/httpd-2.4.18/lib/libcrypto.so.1.0.0
#7  0xb7c8e040 in ssl3_read_n ()
   from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
#8  0xb7c8fa75 in ssl3_read_bytes ()
   from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
#9  0xb7c8c211 in ssl3_read ()
   from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
#10 0xb7ca8679 in SSL_read ()
   from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
#11 0xb7ce80d7 in ssl_io_input_read (inctx=inctx@entry=0x81636e8,
buf=buf@entry=0x8163710 "GET /css/subpage.css HTTP/1.1\r\nUser-Agent: 
curl/7.40.0\r\nHost: na171\r\nAccept: */*\r\n\r\n", len=len@entry=0xb8f8)
at ssl_engine_io.c:611
#12 0xb7cea36c in ssl_io_filter_input (f=0x8165718, bb=0x81660d8,
mode=AP_MODE_SPECULATIVE, block=APR_NONBLOCK_READ, readbytes=1)
at ssl_engine_io.c:1407
#13 0x080a013f in check_pipeline (bb=0x81660d8, c=0x8156eb0)
at http_request.c:244
#14 ap_process_request_after_handler (r=0x817e2d8) at http_request.c:367
#15 0x080a1229 in ap_process_async_request (r=r@entry=0x817e2d8)
at http_request.c:448
#16 0x080a1575 in ap_process_request (r=r@entry=0x817e2d8)
at http_request.c:458
#17 0x0809d547 in ap_process_http_sync_connection (c=0x8156eb0)
at http_core.c:210
#18 ap_process_http_connection (c=0x8156eb0) at http_core.c:251
#19 0x0809549d in ap_run_process_connection (c=0x8156eb0) at connection.c:41
#20 0x0809589d in ap_process_connection (c=c@entry=0x8156eb0, csd=0x8156d18)
at connection.c:213
#21 0x080a7849 in child_main (child_num_arg=child_num_arg@entry=0,
child_bucket=child_bucket@entry=0) at prefork.c:723
#22 0x080a7a9f in make_child (s=0x80f9f38, slot=slot@entry=0,
bucket=bucket@entry=0) at prefork.c:767
#23 0x080a9091 in prefork_run (_pconf=0x80d50a8, plog=0x80fd9b8, s=0x80f9f38)
at prefork.c:979
#24 0x08070959 in ap_run_mpm (pconf=pconf@entry=0x80d50a8, plog=0x80fd9b8,
s=0x80f9f38) at mpm_common.c:94
#25 0x08069f23 in main (argc=4, argv=0xbd54) at main.c:777



On 2016-02-03 11:50 PM, Plüm, Rüdiger, Vodafone Group wrote:


Can you also post the backtrace when the server is hanging in the read?

Regards

Rüdiger


-Original Message-
From: Plüm, Rüdiger, Vodafone Group
Sent: Donnerstag, 4. Februar 2016 08:39
To: dev@httpd.apache.org
Subject: RE: HTTPS connections lock-up with 2.4.18

Thanks. Which version of APR / APR-UTIL are you using?

Regards

Rüdiger


-Original Message-
From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
Sent: Donnerstag, 4. Februar 2016 03:56
To: dev@httpd.apache.org
Subject: Re: HTTPS connections lock-up with 2.4.18

Perhaps, there is an important clue this time. When I retrieve a file
that works we see the following log messages near the time when the
reply is being written:


[Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes

[Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes

[Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client

205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes

[Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA EOS

[Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA EOR

[Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9db96d8] in: read 5 bytes

[Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9db96d8] in: read 26 bytes

[Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End

of

file found: [client 205.159.216.185:55978] check_pipeline: no data

[Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End

of

file found: [client 205.159.216.185:55978] check_pipeline:
data_in_input_filters = 0

[Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client

205.

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

Thanks. This is really strange. I don't get how we could ever end up with a 
blocking socket on OS side.

Regards

Rüdiger

> -Original Message-
> From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
> Sent: Donnerstag, 4. Februar 2016 09:17
> To: dev@httpd.apache.org
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> Here is the backtrace:
> 
> > #0  0xb7fddc40 in __kernel_vsyscall ()
> > #1  0xb7e05f03 in __read_nocancel () at ../sysdeps/unix/syscall-
> template.S:81
> > #2  0xb7f39589 in apr_socket_recv (sock=sock@entry=0x8156d18,
> > buf=buf@entry=0x8168750 "html, body {\n   font-family: arial,
> helvetica, sans-serif;\n   font-size: 12px;\n   height: 100%;\n
> margin:0;\n   padding:0;\n   height:100%;\n}\nbody a, a:hover {\n   text-
> decoration: underline;\n   border:"..., len=len@entry=0xb5e4) at
> network_io/unix/sendrecv.c:81
> > #3  0xb7f744d5 in socket_bucket_read (a=0x8160fc8, str=0xb5e0,
> > len=0xb5e4, block=APR_NONBLOCK_READ)
> > at buckets/apr_buckets_socket.c:36
> > #4  0x08086a98 in ap_core_input_filter (f=0x8165770, b=0x8165730,
> > mode=AP_MODE_READBYTES, block=APR_NONBLOCK_READ, readbytes=5)
> > at core_filters.c:235
> > #5  0xb7ce732a in bio_filter_in_read (bio=0x81666d8, in=0x816bc83 "",
> inlen=5)
> > at ssl_engine_io.c:487
> > #6  0xb7b1bc66 in BIO_read ()
> >from /home/joachima/httpd-2.4.18/lib/libcrypto.so.1.0.0
> > #7  0xb7c8e040 in ssl3_read_n ()
> >from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
> > #8  0xb7c8fa75 in ssl3_read_bytes ()
> >from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
> > #9  0xb7c8c211 in ssl3_read ()
> >from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
> > #10 0xb7ca8679 in SSL_read ()
> >from /home/joachima/httpd-2.4.18/lib/libssl.so.1.0.0
> > #11 0xb7ce80d7 in ssl_io_input_read (inctx=inctx@entry=0x81636e8,
> > buf=buf@entry=0x8163710 "GET /css/subpage.css HTTP/1.1\r\nUser-
> Agent: curl/7.40.0\r\nHost: na171\r\nAccept: */*\r\n\r\n",
> len=len@entry=0xb8f8)
> > at ssl_engine_io.c:611
> > #12 0xb7cea36c in ssl_io_filter_input (f=0x8165718, bb=0x81660d8,
> > mode=AP_MODE_SPECULATIVE, block=APR_NONBLOCK_READ, readbytes=1)
> > at ssl_engine_io.c:1407
> > #13 0x080a013f in check_pipeline (bb=0x81660d8, c=0x8156eb0)
> > at http_request.c:244
> > #14 ap_process_request_after_handler (r=0x817e2d8) at http_request.c:367
> > #15 0x080a1229 in ap_process_async_request (r=r@entry=0x817e2d8)
> > at http_request.c:448
> > #16 0x080a1575 in ap_process_request (r=r@entry=0x817e2d8)
> > at http_request.c:458
> > #17 0x0809d547 in ap_process_http_sync_connection (c=0x8156eb0)
> > at http_core.c:210
> > #18 ap_process_http_connection (c=0x8156eb0) at http_core.c:251
> > #19 0x0809549d in ap_run_process_connection (c=0x8156eb0) at
> connection.c:41
> > #20 0x0809589d in ap_process_connection (c=c@entry=0x8156eb0,
> csd=0x8156d18)
> > at connection.c:213
> > #21 0x080a7849 in child_main (child_num_arg=child_num_arg@entry=0,
> > child_bucket=child_bucket@entry=0) at prefork.c:723
> > #22 0x080a7a9f in make_child (s=0x80f9f38, slot=slot@entry=0,
> > bucket=bucket@entry=0) at prefork.c:767
> > #23 0x080a9091 in prefork_run (_pconf=0x80d50a8, plog=0x80fd9b8,
> s=0x80f9f38)
> > at prefork.c:979
> > #24 0x08070959 in ap_run_mpm (pconf=pconf@entry=0x80d50a8,
> plog=0x80fd9b8,
> > s=0x80f9f38) at mpm_common.c:94
> > #25 0x08069f23 in main (argc=4, argv=0xbd54) at main.c:777
> 
> 
> On 2016-02-03 11:50 PM, Plüm, Rüdiger, Vodafone Group wrote:
> 

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Thu, Feb 4, 2016 at 9:54 AM, Yann Ylavic  wrote:
> On Thu, Feb 4, 2016 at 9:41 AM, Yann Ylavic  wrote:
>> Doesn't the socket_bucket_read() call (frame #3) enter
>> apr_socket_timeout_set(p, 0), and hence sononblock() which puts the
>> socket in O_NONBLOCK?
>
> and resets APR_INCOMPLETE_READ.

Would this help?

Index: srclib/apr/buckets/apr_buckets_socket.c
===
--- srclib/apr/buckets/apr_buckets_socket.c (revision 1568989)
+++ srclib/apr/buckets/apr_buckets_socket.c (working copy)
@@ -26,7 +26,10 @@ static apr_status_t socket_bucket_read(apr_bucket

 if (block == APR_NONBLOCK_READ) {
 apr_socket_timeout_get(p, );
-apr_socket_timeout_set(p, 0);
+rv = apr_socket_timeout_set(p, 0);
+if (rv != APR_SUCCESS) {
+return rv;
+}
 }

 *str = NULL;
--

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

Which MPM is used? Event or something different?
There a differences on how c->data_in_input_filters is handled by different 
MPM's.
On sync MPM's like worker there is an explicit flush if 
c->data_in_input_filters is zero,
the event MPM though only relies on WRITE_COMPLETION.
If event is used, does switching to worker MPM make the issue go away?

Regards

Rüdiger

> -Original Message-
> From: Yann Ylavic [mailto:ylavic@gmail.com]
> Sent: Mittwoch, 3. Februar 2016 11:22
> To: httpd-dev
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> On Wed, Feb 3, 2016 at 10:14 AM, Joachim Achtzehnter <joac...@kraut.ca>
> wrote:
> > Late at night here and I'm not at work, but see the embedded responses
> to
> > clarify some things...
> >
> > On 2016-02-03 12:43 AM, Yann Ylavic wrote:
> >>
> >> I can't tell about the underlying HTTP data here, but I suspect there
> >> is more than a single HTTP request sent by the client,
> 
> Actually I didn't notice that ssltrace-v3.txt contained the plain HTTP
> request (thought it was the text version of the raw capture).
> 
> >
> > No, there is definitely only one request for this test. In the real
> > application there is an HTML page, which triggers multiple requests for
> > style sheets, scripts, images, etc., and these may well be pipelined or
> > submitted via parallel connections. This still locked-up, 100%
> reproducible.
> > The test I use to collect the traces and logs is retrieving a single
> small
> > style sheet. No other files are involved. In order to allow Wireshark to
> > decrypt the SSL data I used Firefox, but for my own testing and
> debugging I
> > usually submit the request with curl. The outcome is the same with both
> > Firefox and curl.
> 
> OK, so there must be an issue in the check_pipeline() function...
> 
> >
> >> which makes httpd believe requests are pipelined,
> >
> >
> > How does it make this determination?
> 
> By reading the pipe (non-blocking) before entering keepalive state,
> and if that succeeds (ignoring blank lines since 2.4.18, another
> change introduced in this version) the next request is processed
> immediatly without flushing output.
> IOW, pipelined requests imply batched responses.
> 
> Could you please provide the output of this new patch on top of the
> previous (latest) one?
> 
> Index: modules/http/http_request.c
> ===
> --- modules/http/http_request.c(revision 1727923)
> +++ modules/http/http_request.c(working copy)
> @@ -254,6 +254,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
>"Can't consume pipelined empty lines");
>  c->keepalive = AP_CONN_CLOSE;
>  }
> +else {
> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
> +  "check_pipeline: no data");
> +}
>  break;
>  }
> 
> @@ -284,6 +288,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
>  break;
>  }
> 
> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
> +  "check_pipeline: got 0x%x",
> +  (int)(cr ? buf[1] : buf[0]));
> +
>  if (mode == AP_MODE_READBYTES) {
>  mode = AP_MODE_SPECULATIVE;
>  cr = 0;
> @@ -319,6 +327,11 @@ static void check_pipeline(conn_rec *c, apr_bucket
>  c->keepalive = AP_CONN_CLOSE;
>  }
>  }
> +
> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
> +  "check_pipeline: data_in_input_filters = %i",
> +  c->data_in_input_filters);
> +
>  }
> 
> --
> 
> Thanks,
> Yann.

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 11:38 AM, Stefan Eissing
 wrote:
> Interesting. I have an issue on github from someone who observes, sometimes, 
> a hanging
> HTTP/2 connection, where mod_http2 calls ap_pass_brigade() with ~120KB which 
> never
> returns. Client, after a while, closes its end of the connection. Connection 
> remains in CLOSE_WAIT.

Where is httpd blocked/stalled, which function?

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Stefan Eissing]

Interesting. I have an issue on github from someone who observes, sometimes, a 
hanging
HTTP/2 connection, where mod_http2 calls ap_pass_brigade() with ~120KB which 
never
returns. Client, after a while, closes its end of the connection. Connection 
remains in CLOSE_WAIT.

Might this be related to the issue reported here? Anyhow I can help?

-Stefan

> Am 03.02.2016 um 11:29 schrieb Plüm, Rüdiger, Vodafone Group 
> <ruediger.pl...@vodafone.com>:
> 
> Which MPM is used? Event or something different?
> There a differences on how c->data_in_input_filters is handled by different 
> MPM's.
> On sync MPM's like worker there is an explicit flush if 
> c->data_in_input_filters is zero,
> the event MPM though only relies on WRITE_COMPLETION.
> If event is used, does switching to worker MPM make the issue go away?
> 
> Regards
> 
> Rüdiger
> 
>> -Original Message-
>> From: Yann Ylavic [mailto:ylavic@gmail.com]
>> Sent: Mittwoch, 3. Februar 2016 11:22
>> To: httpd-dev
>> Subject: Re: HTTPS connections lock-up with 2.4.18
>> 
>> On Wed, Feb 3, 2016 at 10:14 AM, Joachim Achtzehnter <joac...@kraut.ca>
>> wrote:
>>> Late at night here and I'm not at work, but see the embedded responses
>> to
>>> clarify some things...
>>> 
>>> On 2016-02-03 12:43 AM, Yann Ylavic wrote:
>>>> 
>>>> I can't tell about the underlying HTTP data here, but I suspect there
>>>> is more than a single HTTP request sent by the client,
>> 
>> Actually I didn't notice that ssltrace-v3.txt contained the plain HTTP
>> request (thought it was the text version of the raw capture).
>> 
>>> 
>>> No, there is definitely only one request for this test. In the real
>>> application there is an HTML page, which triggers multiple requests for
>>> style sheets, scripts, images, etc., and these may well be pipelined or
>>> submitted via parallel connections. This still locked-up, 100%
>> reproducible.
>>> The test I use to collect the traces and logs is retrieving a single
>> small
>>> style sheet. No other files are involved. In order to allow Wireshark to
>>> decrypt the SSL data I used Firefox, but for my own testing and
>> debugging I
>>> usually submit the request with curl. The outcome is the same with both
>>> Firefox and curl.
>> 
>> OK, so there must be an issue in the check_pipeline() function...
>> 
>>> 
>>>> which makes httpd believe requests are pipelined,
>>> 
>>> 
>>> How does it make this determination?
>> 
>> By reading the pipe (non-blocking) before entering keepalive state,
>> and if that succeeds (ignoring blank lines since 2.4.18, another
>> change introduced in this version) the next request is processed
>> immediatly without flushing output.
>> IOW, pipelined requests imply batched responses.
>> 
>> Could you please provide the output of this new patch on top of the
>> previous (latest) one?
>> 
>> Index: modules/http/http_request.c
>> ===
>> --- modules/http/http_request.c(revision 1727923)
>> +++ modules/http/http_request.c(working copy)
>> @@ -254,6 +254,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
>>   "Can't consume pipelined empty lines");
>> c->keepalive = AP_CONN_CLOSE;
>> }
>> +else {
>> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
>> +  "check_pipeline: no data");
>> +}
>> break;
>> }
>> 
>> @@ -284,6 +288,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
>> break;
>> }
>> 
>> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
>> +  "check_pipeline: got 0x%x",
>> +  (int)(cr ? buf[1] : buf[0]));
>> +
>> if (mode == AP_MODE_READBYTES) {
>> mode = AP_MODE_SPECULATIVE;
>> cr = 0;
>> @@ -319,6 +327,11 @@ static void check_pipeline(conn_rec *c, apr_bucket
>> c->keepalive = AP_CONN_CLOSE;
>> }
>> }
>> +
>> +ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
>> +  "check_pipeline: data_in_input_filters = %i",
>> +  c->data_in_input_filters);
>> +
>> }
>> 
>> --
>> 
>> Thanks,
>> Yann.

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 6:31 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
>
> Attached is file "ssl_log-v3.txt" with the log messages seen when using your
> v3 patch. The other two files are the corresponding Wireshark traces,
> collected on the client-side where Firefox was trying to retrieve the file.

Looks OK on the httpd side now with explicit flushes on write (during
handshake), but the issue seems to be on the client side now.

The "Encrypted Handshake Message" it uses to finalize its handshake
looks really weird, and it doesn't wait for the server to finalize the
handshake before sending the HTTP request (the complete handshake
response will only be read by the client when it expects the HTTP
response).

I can't tell about the underlying HTTP data here, but I suspect there
is more than a single HTTP request sent by the client, which makes
httpd believe requests are pipelined, and hence never flush its output
until the client stops pipelining requests.
The client is now blocked waiting for the first response...

Before 2.4.18, since simply reading on the connection flushed the
output data on the server side, the client had its response while the
server was reading the second (pipelined) request.

I'd need more info to confirm (or invalidate) this, like LogLevel
trace8 (possibly privately, still).

>
> While exploring a final fix for this, can I ask for your opinion about the
> following work-around we currently rely on until there is an official fix.
> We continue to use Apache 2.4.18, but have replaced mod_ssl.so with the one
> from Apache 2.4.12. Is this likely to be safe? or do you not recommend
> mixing versions?

This looks "risky" to me, recompiling 2.4.18 with your original patch
is much better IMHO.

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 10:14 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
> Late at night here and I'm not at work, but see the embedded responses to
> clarify some things...
>
> On 2016-02-03 12:43 AM, Yann Ylavic wrote:
>>
>> I can't tell about the underlying HTTP data here, but I suspect there
>> is more than a single HTTP request sent by the client,

Actually I didn't notice that ssltrace-v3.txt contained the plain HTTP
request (thought it was the text version of the raw capture).

>
> No, there is definitely only one request for this test. In the real
> application there is an HTML page, which triggers multiple requests for
> style sheets, scripts, images, etc., and these may well be pipelined or
> submitted via parallel connections. This still locked-up, 100% reproducible.
> The test I use to collect the traces and logs is retrieving a single small
> style sheet. No other files are involved. In order to allow Wireshark to
> decrypt the SSL data I used Firefox, but for my own testing and debugging I
> usually submit the request with curl. The outcome is the same with both
> Firefox and curl.

OK, so there must be an issue in the check_pipeline() function...

>
>> which makes httpd believe requests are pipelined,
>
>
> How does it make this determination?

By reading the pipe (non-blocking) before entering keepalive state,
and if that succeeds (ignoring blank lines since 2.4.18, another
change introduced in this version) the next request is processed
immediatly without flushing output.
IOW, pipelined requests imply batched responses.

Could you please provide the output of this new patch on top of the
previous (latest) one?

Index: modules/http/http_request.c
===
--- modules/http/http_request.c(revision 1727923)
+++ modules/http/http_request.c(working copy)
@@ -254,6 +254,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
   "Can't consume pipelined empty lines");
 c->keepalive = AP_CONN_CLOSE;
 }
+else {
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
+  "check_pipeline: no data");
+}
 break;
 }

@@ -284,6 +288,10 @@ static void check_pipeline(conn_rec *c, apr_bucket
 break;
 }

+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
+  "check_pipeline: got 0x%x",
+  (int)(cr ? buf[1] : buf[0]));
+
 if (mode == AP_MODE_READBYTES) {
 mode = AP_MODE_SPECULATIVE;
 cr = 0;
@@ -319,6 +327,11 @@ static void check_pipeline(conn_rec *c, apr_bucket
 c->keepalive = AP_CONN_CLOSE;
 }
 }
+
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, rv, c,
+  "check_pipeline: data_in_input_filters = %i",
+  c->data_in_input_filters);
+
 }

--

Thanks,
Yann.

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

What is the configuration of your https hosts? Do you have multiple name based 
one? Did you enable mod_http2?

Regards

Rüdiger

> -Original Message-
> From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
> Sent: Mittwoch, 3. Februar 2016 06:31
> To: dev@httpd.apache.org
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> Hi Yann,
> 
> Attached is file "ssl_log-v3.txt" with the log messages seen when using
> your v3 patch. The other two files are the corresponding Wireshark
> traces, collected on the client-side where Firefox was trying to
> retrieve the file.
> 
> While exploring a final fix for this, can I ask for your opinion about
> the following work-around we currently rely on until there is an
> official fix. We continue to use Apache 2.4.18, but have replaced
> mod_ssl.so with the one from Apache 2.4.12. Is this likely to be safe?
> or do you not recommend mixing versions?
> 
> Thanks,
> 
> Joachim
> 
> 
> 
> On 2016-02-02 4:46, Yann Ylavic wrote:
> > Back to the list...
> > (Attaching the logs provided privately by Joachim, with the client IP
> > - the only possible sensitive informatition - replaced with
> > XXX.XXX.XXX.XXX).
> >
> > On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter <joac...@kraut.ca>
> wrote:
> >>
> >> Applied you patch, built, installed, and then tested. There was no
> >> improvement. I've attached the log messages as "ssl_log-v2.txt".
> >>
> >> The I changed "#if 0" to #if 1" and it is still not working. Th elog
> >> messages for this case are attached as "ssl_log-v2-if1.txt".
> >
> > These logs show that the flush on read is *not* necessary (at least
> > from mod_ssl POV), provided each write is flushed during handshake.
> > Unfortunately OpenSSL does not seem to do it by itself: there is no
> > "bio[%pp] out: FLUSH" outside implicit onces from
> > bio_filter_out_write().
> > So if the "#if 1" patch seems unnecessary, the "#if 0" one looks needed.
> >
> >>
> >> So far, the only version that worked was the old approach, to always
> flush
> >> before blocking on the read.
> >
> > Everything is flushed (during handshake) with this new patch, however
> > we can't say anything about the HTTP response itself at the end of the
> > request (the flushes not initiated by mod_ssl are not logged with my
> > patch, nor LogLevel debug).
> > Attached is (yet) another patch which also outputs METADATA buckets
> > passing through mod_ssl, so that we can see whether the HTTP response
> > is finally flushed or not (there were other changes in 2.4.18
> > regarding this, i.e. in check_pipeline_flush).
> > A simultaneous network capture (pcap) would also be very valuable
> > (btw, where your previous capture taken from, on the server or client
> > side?).
> > This patch shouldn't make it work though, it's just more logging stuff
> > compared to the previous one, unless maybe you change the new "#if 0"
> > (elsewhere this time) to an "#if 1"?
> >
> > Thanks (again) for testing Joachim.
> >
> > Regards,
> > Yann.
> >
> 
> --
> joac...@kraut.ca http://www.kraut.ca

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

What is the size of /css/subpage.css?

Regards

Rüdiger

> -Original Message-
> From: Plüm, Rüdiger, Vodafone Group
> Sent: Mittwoch, 3. Februar 2016 09:19
> To: dev@httpd.apache.org
> Subject: RE: HTTPS connections lock-up with 2.4.18
> 
> What is the configuration of your https hosts? Do you have multiple name
> based one? Did you enable mod_http2?
> 
> Regards
> 
> Rüdiger
> 
> > -Original Message-
> > From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
> > Sent: Mittwoch, 3. Februar 2016 06:31
> > To: dev@httpd.apache.org
> > Subject: Re: HTTPS connections lock-up with 2.4.18
> >
> > Hi Yann,
> >
> > Attached is file "ssl_log-v3.txt" with the log messages seen when using
> > your v3 patch. The other two files are the corresponding Wireshark
> > traces, collected on the client-side where Firefox was trying to
> > retrieve the file.
> >
> > While exploring a final fix for this, can I ask for your opinion about
> > the following work-around we currently rely on until there is an
> > official fix. We continue to use Apache 2.4.18, but have replaced
> > mod_ssl.so with the one from Apache 2.4.12. Is this likely to be safe?
> > or do you not recommend mixing versions?
> >
> > Thanks,
> >
> > Joachim
> >
> >
> >
> > On 2016-02-02 4:46, Yann Ylavic wrote:
> > > Back to the list...
> > > (Attaching the logs provided privately by Joachim, with the client IP
> > > - the only possible sensitive informatition - replaced with
> > > XXX.XXX.XXX.XXX).
> > >
> > > On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter
> <joac...@kraut.ca>
> > wrote:
> > >>
> > >> Applied you patch, built, installed, and then tested. There was no
> > >> improvement. I've attached the log messages as "ssl_log-v2.txt".
> > >>
> > >> The I changed "#if 0" to #if 1" and it is still not working. Th elog
> > >> messages for this case are attached as "ssl_log-v2-if1.txt".
> > >
> > > These logs show that the flush on read is *not* necessary (at least
> > > from mod_ssl POV), provided each write is flushed during handshake.
> > > Unfortunately OpenSSL does not seem to do it by itself: there is no
> > > "bio[%pp] out: FLUSH" outside implicit onces from
> > > bio_filter_out_write().
> > > So if the "#if 1" patch seems unnecessary, the "#if 0" one looks
> needed.
> > >
> > >>
> > >> So far, the only version that worked was the old approach, to always
> > flush
> > >> before blocking on the read.
> > >
> > > Everything is flushed (during handshake) with this new patch, however
> > > we can't say anything about the HTTP response itself at the end of the
> > > request (the flushes not initiated by mod_ssl are not logged with my
> > > patch, nor LogLevel debug).
> > > Attached is (yet) another patch which also outputs METADATA buckets
> > > passing through mod_ssl, so that we can see whether the HTTP response
> > > is finally flushed or not (there were other changes in 2.4.18
> > > regarding this, i.e. in check_pipeline_flush).
> > > A simultaneous network capture (pcap) would also be very valuable
> > > (btw, where your previous capture taken from, on the server or client
> > > side?).
> > > This patch shouldn't make it work though, it's just more logging stuff
> > > compared to the previous one, unless maybe you change the new "#if 0"
> > > (elsewhere this time) to an "#if 1"?
> > >
> > > Thanks (again) for testing Joachim.
> > >
> > > Regards,
> > > Yann.
> > >
> >
> > --
> > joac...@kraut.ca http://www.kraut.ca

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 11:29 AM, Plüm, Rüdiger, Vodafone Group
 wrote:
> Which MPM is used? Event or something different?
> There a differences on how c->data_in_input_filters is handled by different 
> MPM's.
> On sync MPM's like worker there is an explicit flush if 
> c->data_in_input_filters is zero,
> the event MPM though only relies on WRITE_COMPLETION.

Hmm, ap_process_request() really checks for c->data_in_input_filters
to determine whether it should flush or not.
So I don't see it depending on the MPM.

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

Late at night here and I'm not at work, but see the embedded responses 
to clarify some things...


On 2016-02-03 12:43 AM, Yann Ylavic wrote:

On Wed, Feb 3, 2016 at 6:31 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:


Attached is file "ssl_log-v3.txt" with the log messages seen when using your
v3 patch. The other two files are the corresponding Wireshark traces,
collected on the client-side where Firefox was trying to retrieve the file.


Looks OK on the httpd side now with explicit flushes on write (during
handshake), but the issue seems to be on the client side now.

The "Encrypted Handshake Message" it uses to finalize its handshake
looks really weird, and it doesn't wait for the server to finalize the
handshake before sending the HTTP request (the complete handshake
response will only be read by the client when it expects the HTTP
response).

I can't tell about the underlying HTTP data here, but I suspect there
is more than a single HTTP request sent by the client,


No, there is definitely only one request for this test. In the real 
application there is an HTML page, which triggers multiple requests for 
style sheets, scripts, images, etc., and these may well be pipelined or 
submitted via parallel connections. This still locked-up, 100% 
reproducible. The test I use to collect the traces and logs is 
retrieving a single small style sheet. No other files are involved. In 
order to allow Wireshark to decrypt the SSL data I used Firefox, but for 
my own testing and debugging I usually submit the request with curl. The 
outcome is the same with both Firefox and curl.



which makes httpd believe requests are pipelined,


How does it make this determination?


and hence never  flush its output
until the client stops pipelining requests.
The client is now blocked waiting for the first response...


Yes, it is waiting forever.


Before 2.4.18, since simply reading on the connection flushed the
output data on the server side, the client had its response while the
server was reading the second (pipelined) request.


Except that in this test there is no second request.

Some more details: The application offer the exact same Web 
functionality in one of two modes:


1) HTTP only, configuration does not use virtual hosts

2) HTTPS with HTTP redirected to the corresponding HTTPS URL. The exact 
same functionality as above is now defined in a virtual host for port 
number 443. The virtual host for port number 80 simply sends a redirect 
response back to the client.


With Apache 2.4.12 this all works. After upgrading to 2.4.18 mode 1 
still works perfectly, but with mode 2 some https requests never get a 
response and the application stalls.



I'd need more info to confirm (or invalidate) this, like LogLevel
trace8 (possibly privately, still).



While exploring a final fix for this, can I ask for your opinion about the
following work-around we currently rely on until there is an official fix.
We continue to use Apache 2.4.18, but have replaced mod_ssl.so with the one
from Apache 2.4.12. Is this likely to be safe? or do you not recommend
mixing versions?


This looks "risky" to me, recompiling 2.4.18 with your original patch
is much better IMHO.


Thanks,

Joachim



Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 9:43 AM, Yann Ylavic <ylavic@gmail.com> wrote:
>
> I can't tell about the underlying HTTP data here, but I suspect there
> is more than a single HTTP request sent by the client, which makes
> httpd believe requests are pipelined, and hence never flush its output
> until the client stops pipelining requests.
> The client is now blocked waiting for the first response...

I forgot to ask, when it works (either with your patch on 2.4.18 or
with 2.4.12), is the next (keepalive) request triggering an error
message (in the log) or not?

>
> Regards,
> Yann.

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

On 2016-02-03 12:59 AM, Plüm, Rüdiger, Vodafone Group wrote:

What is the size of /css/subpage.css?


It is fairly small, 1698 bytes to be exact. As I wrote in an earlier 
message, it seems that the problem happens with smaller files, but not 
with bigger files. Another file that fails consistently has a size of 
2509 bytes. Three files that work consistently are 3991, 6478, and 
1239621 bytes long, respectively. Might there be something special going 
on if the response, headers plus data, fits in a single bucket?


Thanks,

Joachim



Regards

Rüdiger


-Original Message-
From: Plüm, Rüdiger, Vodafone Group
Sent: Mittwoch, 3. Februar 2016 09:19
To: dev@httpd.apache.org
Subject: RE: HTTPS connections lock-up with 2.4.18

What is the configuration of your https hosts? Do you have multiple name
based one? Did you enable mod_http2?

Regards

Rüdiger


-Original Message-
From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
Sent: Mittwoch, 3. Februar 2016 06:31
To: dev@httpd.apache.org
Subject: Re: HTTPS connections lock-up with 2.4.18

Hi Yann,

Attached is file "ssl_log-v3.txt" with the log messages seen when using
your v3 patch. The other two files are the corresponding Wireshark
traces, collected on the client-side where Firefox was trying to
retrieve the file.

While exploring a final fix for this, can I ask for your opinion about
the following work-around we currently rely on until there is an
official fix. We continue to use Apache 2.4.18, but have replaced
mod_ssl.so with the one from Apache 2.4.12. Is this likely to be safe?
or do you not recommend mixing versions?

Thanks,

Joachim



On 2016-02-02 4:46, Yann Ylavic wrote:

Back to the list...
(Attaching the logs provided privately by Joachim, with the client IP
- the only possible sensitive informatition - replaced with
XXX.XXX.XXX.XXX).

On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter

<joac...@kraut.ca>

wrote:


Applied you patch, built, installed, and then tested. There was no
improvement. I've attached the log messages as "ssl_log-v2.txt".

The I changed "#if 0" to #if 1" and it is still not working. Th elog
messages for this case are attached as "ssl_log-v2-if1.txt".


These logs show that the flush on read is *not* necessary (at least
from mod_ssl POV), provided each write is flushed during handshake.
Unfortunately OpenSSL does not seem to do it by itself: there is no
"bio[%pp] out: FLUSH" outside implicit onces from
bio_filter_out_write().
So if the "#if 1" patch seems unnecessary, the "#if 0" one looks

needed.




So far, the only version that worked was the old approach, to always

flush

before blocking on the read.


Everything is flushed (during handshake) with this new patch, however
we can't say anything about the HTTP response itself at the end of the
request (the flushes not initiated by mod_ssl are not logged with my
patch, nor LogLevel debug).
Attached is (yet) another patch which also outputs METADATA buckets
passing through mod_ssl, so that we can see whether the HTTP response
is finally flushed or not (there were other changes in 2.4.18
regarding this, i.e. in check_pipeline_flush).
A simultaneous network capture (pcap) would also be very valuable
(btw, where your previous capture taken from, on the server or client
side?).
This patch shouldn't make it work though, it's just more logging stuff
compared to the previous one, unless maybe you change the new "#if 0"
(elsewhere this time) to an "#if 1"?

Thanks (again) for testing Joachim.

Regards,
Yann.



--
joac...@kraut.ca http://www.kraut.ca

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

> -Original Message-
> From: Yann Ylavic [mailto:ylavic@gmail.com]
> Sent: Mittwoch, 3. Februar 2016 11:41
> To: httpd-dev
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> On Wed, Feb 3, 2016 at 11:29 AM, Plüm, Rüdiger, Vodafone Group
> <ruediger.pl...@vodafone.com> wrote:
> > Which MPM is used? Event or something different?
> > There a differences on how c->data_in_input_filters is handled by
> different MPM's.
> > On sync MPM's like worker there is an explicit flush if c-
> >data_in_input_filters is zero,
> > the event MPM though only relies on WRITE_COMPLETION.
> 
> Hmm, ap_process_request() really checks for c->data_in_input_filters
> to determine whether it should flush or not.
> So I don't see it depending on the MPM.

It does, because ap_process_request is only called by sync MPMs.
Event calls ap_process_async_request only. See ap_process_http_connection in 
http_core.c


Regards

Rüdiger

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 3:01 PM, Yann Ylavic  wrote:
> On Wed, Feb 3, 2016 at 12:34 PM, Yann Ylavic  wrote:
>>
>> So I don't see why the response is not flushed on the network before
>> entering READ_REQUEST_LINE or CHECK_REQUEST_LINE_READABLE states.
>
> OK, I can now reproduce with mpm_event.

Actually no. I can reproduce the pending data not being flushed by a
FLUSH bucket (which is expected with event), but still event flushes
them by calling the core output filter directly, and it works here...

>
> Joachim, looking into this from my own environment (no need to apply
> patches yourself now ;)

So unfortunately there seem to be something special in your
environment which prevents non-blocking writes to go out (not talking
about the weird TLS handshake played by the client according to the
pcap).

Could you try Rüdiger's (logging) patch?
And maybe take network traces on the server side?

Thanks,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Ruediger Pluem]

On 02/03/2016 12:34 PM, Yann Ylavic wrote:
> On Wed, Feb 3, 2016 at 11:53 AM, Plüm, Rüdiger, Vodafone Group
> <ruediger.pl...@vodafone.com> wrote:
>>
>>> -Original Message-
>>> From: Yann Ylavic [mailto:ylavic@gmail.com]
>>> Sent: Mittwoch, 3. Februar 2016 11:41
>>> To: httpd-dev
>>> Subject: Re: HTTPS connections lock-up with 2.4.18
>>>
>>> On Wed, Feb 3, 2016 at 11:29 AM, Plüm, Rüdiger, Vodafone Group
>>> <ruediger.pl...@vodafone.com> wrote:
>>>> Which MPM is used? Event or something different?
>>>> There a differences on how c->data_in_input_filters is handled by
>>> different MPM's.
>>>> On sync MPM's like worker there is an explicit flush if c-
>>>> data_in_input_filters is zero,
>>>> the event MPM though only relies on WRITE_COMPLETION.
>>>
>>> Hmm, ap_process_request() really checks for c->data_in_input_filters
>>> to determine whether it should flush or not.
>>> So I don't see it depending on the MPM.
>>
>> It does, because ap_process_request is only called by sync MPMs.
>> Event calls ap_process_async_request only. See ap_process_http_connection in 
>> http_core.c
> 
> Oh right, sorry, I completely misread your message and thought you
> were saying that sync MPMs do flush unconditionally :/
> 
> But still event should (try to) flush pending data when in
> WRITE_COMPLETION while c->data_in_output_filters (calling the
> core_output_filter() with NULL brigade).
> So I don't see why the response is not flushed on the network before
> entering READ_REQUEST_LINE or CHECK_REQUEST_LINE_READABLE states.

I do not get this either, but maybe some additional debug messages in
ap_core_output_filter / send_brigade_nonblocking will help us understanding 
this.

Something like this:

Index: server/core_filters.c
===
--- server/core_filters.c   (revision 1728304)
+++ server/core_filters.c   (working copy)
@@ -465,6 +465,12 @@
  */

 if (new_bb == NULL) {
+apr_off_t blen;
+
+rv = apr_brigade_length(bb, 1, );
+ap_log_cerror(APLOG_MARK, APLOG_DEBUG, rv, c,
+  "core_output_filter: writing data to the network: 
Brigade length: %" APR_OFF_T_FMT,
+  blen);
 rv = send_brigade_nonblocking(net->client_socket, bb,
   &(ctx->bytes_written), c);
 if (rv != APR_SUCCESS && !APR_STATUS_IS_EAGAIN(rv)) {
@@ -702,6 +708,10 @@
 }

 if (nvec > 0) {
+ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c,
+  "send_brigade_nonblocking: calling writev_nonblocking, 
nvec: %"
+  APR_SIZE_T_FMT " , bytes_written: %" APR_SIZE_T_FMT,
+  nvec, *bytes_written);
 rv = writev_nonblocking(s, vec, nvec, bb, bytes_written, c);
 if (rv != APR_SUCCESS) {
 return rv;



Regards

Rüdiger

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 12:34 PM, Yann Ylavic  wrote:
>
> So I don't see why the response is not flushed on the network before
> entering READ_REQUEST_LINE or CHECK_REQUEST_LINE_READABLE states.

OK, I can now reproduce with mpm_event.

Joachim, looking into this from my own environment (no need to apply
patches yourself now ;)

>
> Regards,
> Yann.

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

Perhaps, there is an important clue this time. When I retrieve a file 
that works we see the following log messages near the time when the 
reply is being written:



[Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes
[Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes
[Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client 
205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes
[Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: METADATA EOS
[Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: METADATA EOR
[Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9db96d8] in: read 5 bytes
[Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9db96d8] in: read 26 bytes
[Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End of file 
found: [client 205.159.216.185:55978] check_pipeline: no data
[Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End of file 
found: [client 205.159.216.185:55978] check_pipeline: data_in_input_filters = 0
[Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
[Wed Feb 03 18:13:51.406591 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
[Wed Feb 03 18:13:51.406613 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: METADATA EOC
[Wed Feb 03 18:13:51.406624 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: pass 31 bytes
[Wed Feb 03 18:13:51.406673 2016] [ssl:notice] [pid 1676] [client 
205.159.216.185:55978] bio[9dabd50] out: FLUSH
[Wed Feb 03 18:13:51.406723 2016] [core:notice] [pid 1676] [client 
205.159.216.185:55978] core_output_filter: sent 31 on 31 bytes
[Wed Feb 03 18:13:51.406735 2016] [ssl:debug] [pid 1676] ssl_engine_io.c(1029): 
[client 205.159.216.185:55978] AH02001: Connection closed to child 0 with 
standard shutdown (server localhost:443)


Notice the call to check_pipeline returns quickly. Now the same part of 
the log for the failing file:



[Wed Feb 03 17:56:55.424124 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: pass 271 bytes
[Wed Feb 03 17:56:55.424192 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: pass 1727 bytes
[Wed Feb 03 17:56:55.424223 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: METADATA EOS
[Wed Feb 03 17:56:55.424235 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: METADATA EOR
[Wed Feb 03 18:09:56.652288 2016] [http:notice] [pid 1663] (11)Resource 
temporarily unavailable: [client 205.159.216.185:55962] check_pipeline: no data
[Wed Feb 03 18:09:56.652376 2016] [http:notice] [pid 1663] (11)Resource 
temporarily unavailable: [client 205.159.216.185:55962] check_pipeline: 
data_in_input_filters = 0
[Wed Feb 03 18:09:56.652398 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
[Wed Feb 03 18:09:56.652444 2016] [core:notice] [pid 1663] [client 
205.159.216.185:55962] core_output_filter: sent 1998 on 1998 bytes
[Wed Feb 03 18:09:56.652510 2016] [ssl:info] [pid 1663] (70014)End of file 
found: [client 205.159.216.185:55962] AH01991: SSL input filter read failed.
[Wed Feb 03 18:09:56.652519 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
[Wed Feb 03 18:09:56.652525 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: METADATA EOC
[Wed Feb 03 18:09:56.652545 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: pass 31 bytes
[Wed Feb 03 18:09:56.652553 2016] [ssl:notice] [pid 1663] [client 
205.159.216.185:55962] bio[8158d50] out: FLUSH
[Wed Feb 03 18:09:56.652568 2016] [core:notice] [pid 1663] [client 
205.159.216.185:55962] core_output_filter: sent 31 on 31 bytes
[Wed Feb 03 18:09:56.652576 2016] [ssl:debug] [pid 1663] ssl_engine_io.c(1029): 
[client 205.159.216.185:55962] AH02001: Connection closed to child 0 with 
standard shutdown (server localhost:443)


The check_pipeline call only returns when I kill the client. I first 
noticed this in the debugger where httpd was sitting in a blocking read. 
Somehow, in this case a blocking read is done instead of a non-blocking 
read.


To be specific, it ended up in the do/while loop that calls read in 
function apr_socket_recv (sendrecv.c), called from socket_bucket_read in 
apr_buckets_socket.c, called from ap_core_input_filter in 
core_filters.c. The block parameter was APR_NONBLOCK_READ, but this 
didn't stop the lower-level functions from blocking, somehow. The 
apr_socket_recv function 

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 4:01 PM, Yann Ylavic  wrote:
> On Wed, Feb 3, 2016 at 3:01 PM, Yann Ylavic  wrote:
>>
>> Joachim, looking into this from my own environment (no need to apply
>> patches yourself now ;)
>
> So unfortunately there seem to be something special in your
> environment which prevents non-blocking writes to go out (not talking
> about the weird TLS handshake played by the client according to the
> pcap).
>
> Could you try Rüdiger's (logging) patch?

I suggest you use the attached patch instead (replacing any previous
one), so that we log the output path taken when mod_ssl is in the
place.

> And maybe take network traces on the server side?

That would be really nice too.

>
> Thanks,
> Yann.


modssl_ssl_need_flush-v4.patch
Description: application/download

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

Thanks. Which version of APR / APR-UTIL are you using?

Regards

Rüdiger

> -Original Message-
> From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
> Sent: Donnerstag, 4. Februar 2016 03:56
> To: dev@httpd.apache.org
> Subject: Re: HTTPS connections lock-up with 2.4.18
> 
> Perhaps, there is an important clue this time. When I retrieve a file
> that works we see the following log messages near the time when the
> reply is being written:
> 
> > [Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes
> > [Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes
> > [Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client
> 205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes
> > [Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: METADATA EOS
> > [Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: METADATA EOR
> > [Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9db96d8] in: read 5 bytes
> > [Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9db96d8] in: read 26 bytes
> > [Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End of
> file found: [client 205.159.216.185:55978] check_pipeline: no data
> > [Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End of
> file found: [client 205.159.216.185:55978] check_pipeline:
> data_in_input_filters = 0
> > [Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > [Wed Feb 03 18:13:51.406591 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > [Wed Feb 03 18:13:51.406613 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: METADATA EOC
> > [Wed Feb 03 18:13:51.406624 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: pass 31 bytes
> > [Wed Feb 03 18:13:51.406673 2016] [ssl:notice] [pid 1676] [client
> 205.159.216.185:55978] bio[9dabd50] out: FLUSH
> > [Wed Feb 03 18:13:51.406723 2016] [core:notice] [pid 1676] [client
> 205.159.216.185:55978] core_output_filter: sent 31 on 31 bytes
> > [Wed Feb 03 18:13:51.406735 2016] [ssl:debug] [pid 1676]
> ssl_engine_io.c(1029): [client 205.159.216.185:55978] AH02001: Connection
> closed to child 0 with standard shutdown (server localhost:443)
> 
> Notice the call to check_pipeline returns quickly. Now the same part of
> the log for the failing file:
> 
> > [Wed Feb 03 17:56:55.424124 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: pass 271 bytes
> > [Wed Feb 03 17:56:55.424192 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: pass 1727 bytes
> > [Wed Feb 03 17:56:55.424223 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: METADATA EOS
> > [Wed Feb 03 17:56:55.424235 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: METADATA EOR
> > [Wed Feb 03 18:09:56.652288 2016] [http:notice] [pid 1663] (11)Resource
> temporarily unavailable: [client 205.159.216.185:55962] check_pipeline: no
> data
> > [Wed Feb 03 18:09:56.652376 2016] [http:notice] [pid 1663] (11)Resource
> temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
> data_in_input_filters = 0
> > [Wed Feb 03 18:09:56.652398 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
> > [Wed Feb 03 18:09:56.652444 2016] [core:notice] [pid 1663] [client
> 205.159.216.185:55962] core_output_filter: sent 1998 on 1998 bytes
> > [Wed Feb 03 18:09:56.652510 2016] [ssl:info] [pid 1663] (70014)End of
> file found: [client 205.159.216.185:55962] AH01991: SSL input filter read
> failed.
> > [Wed Feb 03 18:09:56.652519 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
> > [Wed Feb 03 18:09:56.652525 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: METADATA EOC
> > [Wed Feb 03 18:09:56.652545 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: pass 31 bytes
> > [Wed Feb 03 18:09:56.652553 2016] [ssl:notice] [pid 1663] [client
> 205.159.216.185:55962] bio[8158d50] out: FLUSH
> > [Wed Feb 03 18:09:56.652568 2016] [core:notice] [pid 1663] [client
> 205.159.216.185:55962] core_output_filter: sent 31 on 31 bytes
>

RE: HTTPS connections lock-up with 2.4.18

[Plüm , Rüdiger , Vodafone Group]

Can you also post the backtrace when the server is hanging in the read?

Regards

Rüdiger

> -Original Message-
> From: Plüm, Rüdiger, Vodafone Group
> Sent: Donnerstag, 4. Februar 2016 08:39
> To: dev@httpd.apache.org
> Subject: RE: HTTPS connections lock-up with 2.4.18
> 
> Thanks. Which version of APR / APR-UTIL are you using?
> 
> Regards
> 
> Rüdiger
> 
> > -Original Message-
> > From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
> > Sent: Donnerstag, 4. Februar 2016 03:56
> > To: dev@httpd.apache.org
> > Subject: Re: HTTPS connections lock-up with 2.4.18
> >
> > Perhaps, there is an important clue this time. When I retrieve a file
> > that works we see the following log messages near the time when the
> > reply is being written:
> >
> > > [Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes
> > > [Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes
> > > [Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client
> > 205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes
> > > [Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOS
> > > [Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOR
> > > [Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9db96d8] in: read 5 bytes
> > > [Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9db96d8] in: read 26 bytes
> > > [Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End
> of
> > file found: [client 205.159.216.185:55978] check_pipeline: no data
> > > [Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End
> of
> > file found: [client 205.159.216.185:55978] check_pipeline:
> > data_in_input_filters = 0
> > > [Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > > [Wed Feb 03 18:13:51.406591 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > > [Wed Feb 03 18:13:51.406613 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOC
> > > [Wed Feb 03 18:13:51.406624 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 31 bytes
> > > [Wed Feb 03 18:13:51.406673 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: FLUSH
> > > [Wed Feb 03 18:13:51.406723 2016] [core:notice] [pid 1676] [client
> > 205.159.216.185:55978] core_output_filter: sent 31 on 31 bytes
> > > [Wed Feb 03 18:13:51.406735 2016] [ssl:debug] [pid 1676]
> > ssl_engine_io.c(1029): [client 205.159.216.185:55978] AH02001:
> Connection
> > closed to child 0 with standard shutdown (server localhost:443)
> >
> > Notice the call to check_pipeline returns quickly. Now the same part of
> > the log for the failing file:
> >
> > > [Wed Feb 03 17:56:55.424124 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: pass 271 bytes
> > > [Wed Feb 03 17:56:55.424192 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: pass 1727 bytes
> > > [Wed Feb 03 17:56:55.424223 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA EOS
> > > [Wed Feb 03 17:56:55.424235 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA EOR
> > > [Wed Feb 03 18:09:56.652288 2016] [http:notice] [pid 1663]
> (11)Resource
> > temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
> no
> > data
> > > [Wed Feb 03 18:09:56.652376 2016] [http:notice] [pid 1663]
> (11)Resource
> > temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
> > data_in_input_filters = 0
> > > [Wed Feb 03 18:09:56.652398 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
> > > [Wed Feb 03 18:09:56.652444 2016] [core:notice] [pid 1663] [client
> > 205.159.216.185:55962] core_output_filter: sent 1998 on 1998 bytes
> > > [Wed Feb 03 18:09:56.652510 2016] [ssl:info] [pid 1663] (70014)End of
> > file found: [client 205.159.216.185:55962] AH01991: SSL input filter
> read
> >

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

On 03/02/16 11:38 PM, Plüm, Rüdiger, Vodafone Group wrote:


Thanks. Which version of APR / APR-UTIL are you using?


For diagnostics and debugging of this issue I had downloaded the 
"httpd-2.4.18-deps.tar.bz2" archive and am using the apr/apr-utils 
packages in this archive. This seems to be apr v1.5.2 and apr-utils v1.5.4.


Joachim




Regards

Rüdiger


-Original Message-
From: Joachim Achtzehnter [mailto:joac...@kraut.ca]
Sent: Donnerstag, 4. Februar 2016 03:56
To: dev@httpd.apache.org
Subject: Re: HTTPS connections lock-up with 2.4.18

Perhaps, there is an important clue this time. When I retrieve a file
that works we see the following log messages near the time when the
reply is being written:


[Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes

[Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes

[Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client

205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes

[Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA EOS

[Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA EOR

[Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9db96d8] in: read 5 bytes

[Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9db96d8] in: read 26 bytes

[Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End of

file found: [client 205.159.216.185:55978] check_pipeline: no data

[Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End of

file found: [client 205.159.216.185:55978] check_pipeline:
data_in_input_filters = 0

[Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH

[Wed Feb 03 18:13:51.406591 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH

[Wed Feb 03 18:13:51.406613 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: METADATA EOC

[Wed Feb 03 18:13:51.406624 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: pass 31 bytes

[Wed Feb 03 18:13:51.406673 2016] [ssl:notice] [pid 1676] [client

205.159.216.185:55978] bio[9dabd50] out: FLUSH

[Wed Feb 03 18:13:51.406723 2016] [core:notice] [pid 1676] [client

205.159.216.185:55978] core_output_filter: sent 31 on 31 bytes

[Wed Feb 03 18:13:51.406735 2016] [ssl:debug] [pid 1676]

ssl_engine_io.c(1029): [client 205.159.216.185:55978] AH02001: Connection
closed to child 0 with standard shutdown (server localhost:443)

Notice the call to check_pipeline returns quickly. Now the same part of
the log for the failing file:


[Wed Feb 03 17:56:55.424124 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: pass 271 bytes

[Wed Feb 03 17:56:55.424192 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: pass 1727 bytes

[Wed Feb 03 17:56:55.424223 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: METADATA EOS

[Wed Feb 03 17:56:55.424235 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: METADATA EOR

[Wed Feb 03 18:09:56.652288 2016] [http:notice] [pid 1663] (11)Resource

temporarily unavailable: [client 205.159.216.185:55962] check_pipeline: no
data

[Wed Feb 03 18:09:56.652376 2016] [http:notice] [pid 1663] (11)Resource

temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
data_in_input_filters = 0

[Wed Feb 03 18:09:56.652398 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH

[Wed Feb 03 18:09:56.652444 2016] [core:notice] [pid 1663] [client

205.159.216.185:55962] core_output_filter: sent 1998 on 1998 bytes

[Wed Feb 03 18:09:56.652510 2016] [ssl:info] [pid 1663] (70014)End of

file found: [client 205.159.216.185:55962] AH01991: SSL input filter read
failed.

[Wed Feb 03 18:09:56.652519 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH

[Wed Feb 03 18:09:56.652525 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: METADATA EOC

[Wed Feb 03 18:09:56.652545 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: pass 31 bytes

[Wed Feb 03 18:09:56.652553 2016] [ssl:notice] [pid 1663] [client

205.159.216.185:55962] bio[8158d50] out: FLUSH

[Wed Feb 03 18:09:56.652568 2016] [core:notice] [pid 1663] [client

205.159.216.185:55962] core_output_filter: sent 31 on 31 bytes

[Wed Feb 03 18:09:56.652576 2016] [ssl:debug] [pid 1663]

ssl_engine_io.c(1029): [client 205.159.216.185:55962] AH02001: Connection
closed to child 0 with standard shutdown (server loc

Re: HTTPS connections lock-up with 2.4.18

[Stefan Eissing]

> Am 03.02.2016 um 11:47 schrieb Yann Ylavic :
> 
> On Wed, Feb 3, 2016 at 11:38 AM, Stefan Eissing
>  wrote:
>> Interesting. I have an issue on github from someone who observes, sometimes, 
>> a hanging
>> HTTP/2 connection, where mod_http2 calls ap_pass_brigade() with ~120KB which 
>> never
>> returns. Client, after a while, closes its end of the connection. Connection 
>> remains in CLOSE_WAIT.
> 
> Where is httpd blocked/stalled, which function?

Trying to get a backtrace. Unable to reproduce this myself...

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 11:53 AM, Plüm, Rüdiger, Vodafone Group
<ruediger.pl...@vodafone.com> wrote:
>
>> -Original Message-
>> From: Yann Ylavic [mailto:ylavic@gmail.com]
>> Sent: Mittwoch, 3. Februar 2016 11:41
>> To: httpd-dev
>> Subject: Re: HTTPS connections lock-up with 2.4.18
>>
>> On Wed, Feb 3, 2016 at 11:29 AM, Plüm, Rüdiger, Vodafone Group
>> <ruediger.pl...@vodafone.com> wrote:
>> > Which MPM is used? Event or something different?
>> > There a differences on how c->data_in_input_filters is handled by
>> different MPM's.
>> > On sync MPM's like worker there is an explicit flush if c-
>> >data_in_input_filters is zero,
>> > the event MPM though only relies on WRITE_COMPLETION.
>>
>> Hmm, ap_process_request() really checks for c->data_in_input_filters
>> to determine whether it should flush or not.
>> So I don't see it depending on the MPM.
>
> It does, because ap_process_request is only called by sync MPMs.
> Event calls ap_process_async_request only. See ap_process_http_connection in 
> http_core.c

Oh right, sorry, I completely misread your message and thought you
were saying that sync MPMs do flush unconditionally :/

But still event should (try to) flush pending data when in
WRITE_COMPLETION while c->data_in_output_filters (calling the
core_output_filter() with NULL brigade).
So I don't see why the response is not flushed on the network before
entering READ_REQUEST_LINE or CHECK_REQUEST_LINE_READABLE states.

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Wed, Feb 3, 2016 at 4:53 PM, Yann Ylavic  wrote:
>
> I suggest you use the attached patch instead (replacing any previous
> one), so that we log the output path taken when mod_ssl is in the
> place.

Forgot about the casting issue (SSL_get_app_data) with your compiler...
This v5 (attached) should compile fine.

>
>> And maybe take network traces on the server side?
>
> That would be really nice too.
>
>>
>> Thanks,
>> Yann.


modssl_ssl_need_flush-v5.patch
Description: application/download

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

Hi Yann,

Attached is file "ssl_log-v3.txt" with the log messages seen when using 
your v3 patch. The other two files are the corresponding Wireshark 
traces, collected on the client-side where Firefox was trying to 
retrieve the file.


While exploring a final fix for this, can I ask for your opinion about 
the following work-around we currently rely on until there is an 
official fix. We continue to use Apache 2.4.18, but have replaced 
mod_ssl.so with the one from Apache 2.4.12. Is this likely to be safe? 
or do you not recommend mixing versions?


Thanks,

Joachim



On 2016-02-02 4:46, Yann Ylavic wrote:

Back to the list...
(Attaching the logs provided privately by Joachim, with the client IP
- the only possible sensitive informatition - replaced with
XXX.XXX.XXX.XXX).

On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:


Applied you patch, built, installed, and then tested. There was no
improvement. I've attached the log messages as "ssl_log-v2.txt".

The I changed "#if 0" to #if 1" and it is still not working. Th elog
messages for this case are attached as "ssl_log-v2-if1.txt".


These logs show that the flush on read is *not* necessary (at least
from mod_ssl POV), provided each write is flushed during handshake.
Unfortunately OpenSSL does not seem to do it by itself: there is no
"bio[%pp] out: FLUSH" outside implicit onces from
bio_filter_out_write().
So if the "#if 1" patch seems unnecessary, the "#if 0" one looks needed.



So far, the only version that worked was the old approach, to always flush
before blocking on the read.


Everything is flushed (during handshake) with this new patch, however
we can't say anything about the HTTP response itself at the end of the
request (the flushes not initiated by mod_ssl are not logged with my
patch, nor LogLevel debug).
Attached is (yet) another patch which also outputs METADATA buckets
passing through mod_ssl, so that we can see whether the HTTP response
is finally flushed or not (there were other changes in 2.4.18
regarding this, i.e. in check_pipeline_flush).
A simultaneous network capture (pcap) would also be very valuable
(btw, where your previous capture taken from, on the server or client
side?).
This patch shouldn't make it work though, it's just more logging stuff
compared to the previous one, unless maybe you change the new "#if 0"
(elsewhere this time) to an "#if 1"?

Thanks (again) for testing Joachim.

Regards,
Yann.



--
joac...@kraut.ca http://www.kraut.ca
No. Time   SourceDestination   Protocol 
Info
  1 21:16:23.810518205.159.216.152   205.159.216.171   TCP  
58210 → https [SYN] Seq=760404415 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1

Frame 1: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d 
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443), 
Seq: 760404415, Len: 0

No. Time   SourceDestination   Protocol 
Info
  2 21:16:23.810698205.159.216.171   205.159.216.152   TCP  
https → 58210 [SYN, ACK] Seq=2136556075 Ack=760404416 Win=29200 Len=0 MSS=1460 
SACK_PERM=1 WS=128

Frame 2: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a 
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210), 
Seq: 2136556075, Ack: 760404416, Len: 0

No. Time   SourceDestination   Protocol 
Info
  3 21:16:23.810731205.159.216.152   205.159.216.171   TCP  
58210 → https [ACK] Seq=760404416 Ack=2136556076 Win=65536 Len=0

Frame 3: 54 bytes on wire (432 bits), 54 bytes captured (432 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d 
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443), 
Seq: 760404416, Ack: 2136556076, Len: 0

No. Time   SourceDestination   Protocol 
Info
  4 21:16:23.810883205.159.216.152   205.159.216.171   TLSv1.2  
Client Hello

Frame 4: 233 bytes on wire (1864 bits), 233 bytes captured (1864 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d 
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443), 
Seq: 760404416, Ack: 2136556076, Len: 179
Secure Sockets Layer
TLSv1.2 Record 

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Mon, Feb 1, 2016 at 11:50 PM, Joachim Achtzehnter  wrote:
> The Wireshark trace confirms what one may have predicted from the
> observed symptoms. There is no response from the server to the GET
> request on the wire.

There are some missing TLS records from the server during handshake,
OpenSSL does not seem to flush appropriately, still...

Could you please try this new (attached) patch?
If it does not work better (it should), could you change the "#if 0"
to "#if 1" in bio_filter_in_read(), and retry?
Thanks for providing the log output with the new change(s).

Regards,
Yann.
Index: modules/ssl/ssl_engine_io.c
===
--- modules/ssl/ssl_engine_io.c	(revision 1727923)
+++ modules/ssl/ssl_engine_io.c	(working copy)
@@ -147,6 +147,9 @@ static int bio_filter_out_flush(BIO *bio)
 bio_filter_out_ctx_t *outctx = (bio_filter_out_ctx_t *)(bio->ptr);
 apr_bucket *e;
 
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] out: FLUSH", bio);
+
 AP_DEBUG_ASSERT(APR_BRIGADE_EMPTY(outctx->bb));
 
 e = apr_bucket_flush_create(outctx->bb->bucket_alloc);
@@ -187,7 +190,6 @@ static int bio_filter_out_write(BIO *bio, const ch
 {
 bio_filter_out_ctx_t *outctx = (bio_filter_out_ctx_t *)(bio->ptr);
 apr_bucket *e;
-int need_flush;
 
 /* Abort early if the client has initiated a renegotiation. */
 if (outctx->filter_ctx->config->reneg_state == RENEG_ABORT) {
@@ -216,15 +218,16 @@ static int bio_filter_out_write(BIO *bio, const ch
  * be expensive in cases where requests/reponses are pipelined,
  * so limit the performance impact to handshake time.
  */
-#if OPENSSL_VERSION_NUMBER < 0x0009080df
- need_flush = !SSL_is_init_finished(outctx->filter_ctx->pssl);
-#else
- need_flush = SSL_in_connect_init(outctx->filter_ctx->pssl);
-#endif
-if (need_flush) {
+if (!SSL_is_init_finished(outctx->filter_ctx->pssl)) {
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] out: flush %d bytes", bio, inl);
 e = apr_bucket_flush_create(outctx->bb->bucket_alloc);
 APR_BRIGADE_INSERT_TAIL(outctx->bb, e);
 }
+else {
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] out: pass %d bytes", bio, inl);
+}
 
 if (bio_filter_out_pass(outctx) < 0) {
 return -1;
@@ -473,6 +476,18 @@ static int bio_filter_in_read(BIO *bio, char *in,
 return -1;
 }
 
+#if 0
+if (!SSL_is_init_finished(inctx->filter_ctx->pssl)) {
+bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] in: flush %pp", bio, inctx->bio_out);
+if (bio_filter_out_flush(inctx->bio_out) < 0) {
+inctx->rc = outctx->rc;
+return -1;
+}
+}
+#endif
+
 if (APR_BRIGADE_EMPTY(inctx->bb)) {
 
 inctx->rc = ap_get_brigade(inctx->f->next, inctx->bb,
@@ -499,6 +514,10 @@ static int bio_filter_in_read(BIO *bio, char *in,
 
 inctx->rc = brigade_consume(inctx->bb, block, in, );
 
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, inctx->rc,
+  SSL_get_app_data(inctx->filter_ctx->pssl),
+  "bio[%pp] in: read %" APR_SIZE_T_FMT "bytes", bio, inl);
+
 if (inctx->rc == APR_SUCCESS) {
 return (int)inl;
 }

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

Back to the list...
(Attaching the logs provided privately by Joachim, with the client IP
- the only possible sensitive informatition - replaced with
XXX.XXX.XXX.XXX).

On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
>
> Applied you patch, built, installed, and then tested. There was no
> improvement. I've attached the log messages as "ssl_log-v2.txt".
>
> The I changed "#if 0" to #if 1" and it is still not working. Th elog
> messages for this case are attached as "ssl_log-v2-if1.txt".

These logs show that the flush on read is *not* necessary (at least
from mod_ssl POV), provided each write is flushed during handshake.
Unfortunately OpenSSL does not seem to do it by itself: there is no
"bio[%pp] out: FLUSH" outside implicit onces from
bio_filter_out_write().
So if the "#if 1" patch seems unnecessary, the "#if 0" one looks needed.

>
> So far, the only version that worked was the old approach, to always flush
> before blocking on the read.

Everything is flushed (during handshake) with this new patch, however
we can't say anything about the HTTP response itself at the end of the
request (the flushes not initiated by mod_ssl are not logged with my
patch, nor LogLevel debug).
Attached is (yet) another patch which also outputs METADATA buckets
passing through mod_ssl, so that we can see whether the HTTP response
is finally flushed or not (there were other changes in 2.4.18
regarding this, i.e. in check_pipeline_flush).
A simultaneous network capture (pcap) would also be very valuable
(btw, where your previous capture taken from, on the server or client
side?).
This patch shouldn't make it work though, it's just more logging stuff
compared to the previous one, unless maybe you change the new "#if 0"
(elsewhere this time) to an "#if 1"?

Thanks (again) for testing Joachim.

Regards,
Yann.


modssl_ssl_need_flush-v3.patch
Description: application/download

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Tue, Feb 2, 2016 at 1:46 PM, Yann Ylavic  wrote:
> Back to the list...
> (Attaching the logs provided privately by Joachim, with the client IP
> - the only possible sensitive informatition - replaced with
> XXX.XXX.XXX.XXX).

Oups, here there are.
[Tue Feb 02 01:46:14.452666 2016] [ssl:info] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] AH01964: Connection to child 0 established (server 
localhost:443)
[Tue Feb 02 01:46:14.452986 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 11bytes
[Tue Feb 02 01:46:14.453011 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 156bytes
[Tue Feb 02 01:46:14.453048 2016] [ssl:debug] [pid 2646] 
ssl_engine_kernel.c(2103): [client XXX.XXX.XXX.XXX:47816] AH02044: No matching 
SSL virtual host for servername na171 found (using default/first virtual host)
[Tue Feb 02 01:46:14.458737 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: flush 1004 bytes
[Tue Feb 02 01:46:14.458774 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: FLUSH
[Tue Feb 02 01:46:14.464250 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 5bytes
[Tue Feb 02 01:46:14.464265 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 70bytes
[Tue Feb 02 01:46:14.466307 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 5bytes
[Tue Feb 02 01:46:14.466325 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 1bytes
[Tue Feb 02 01:46:14.466397 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 5bytes
[Tue Feb 02 01:46:14.466412 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 40bytes
[Tue Feb 02 01:46:14.466472 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: flush 51 bytes
[Tue Feb 02 01:46:14.466489 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: FLUSH
[Tue Feb 02 01:46:14.466541 2016] [socache_shmcb:debug] [pid 2646] 
mod_socache_shmcb.c(491): AH00831: socache_shmcb_store (0x10 -> subcache 16)
[Tue Feb 02 01:46:14.466560 2016] [socache_shmcb:debug] [pid 2646] 
mod_socache_shmcb.c(845): AH00847: insert happened at idx=0, data=(0:32)
[Tue Feb 02 01:46:14.466566 2016] [socache_shmcb:debug] [pid 2646] 
mod_socache_shmcb.c(850): AH00848: finished insert, subcache: 
idx_pos/idx_used=0/1, data_pos/data_used=0/189
[Tue Feb 02 01:46:14.466571 2016] [socache_shmcb:debug] [pid 2646] 
mod_socache_shmcb.c(512): AH00834: leaving socache_shmcb_store successfully
[Tue Feb 02 01:46:14.466583 2016] [ssl:debug] [pid 2646] 
ssl_engine_kernel.c(2023): [client XXX.XXX.XXX.XXX:47816] AH02041: Protocol: 
TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
[Tue Feb 02 01:46:14.467273 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 5bytes
[Tue Feb 02 01:46:14.467286 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[87666d8] in: read 108bytes
[Tue Feb 02 01:46:14.467355 2016] [ssl:debug] [pid 2646] 
ssl_engine_kernel.c(354): [client XXX.XXX.XXX.XXX:47816] AH02034: Initial 
(No.1) HTTPS request received for child 0 (server localhost:443)
[Tue Feb 02 01:46:14.467537 2016] [authz_core:debug] [pid 2646] 
mod_authz_core.c(809): [client XXX.XXX.XXX.XXX:47816] AH01626: authorization 
result of Require all granted: granted
[Tue Feb 02 01:46:14.467546 2016] [authz_core:debug] [pid 2646] 
mod_authz_core.c(809): [client XXX.XXX.XXX.XXX:47816] AH01626: authorization 
result of : granted
[Tue Feb 02 01:46:14.467623 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: pass 271 bytes
[Tue Feb 02 01:46:14.467692 2016] [ssl:notice] [pid 2646] [client 
XXX.XXX.XXX.XXX:47816] bio[8758d50] out: pass 1727 bytes
[Tue Feb 02 01:51:56.674022 2016] [ssl:info] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] AH01964: Connection to child 1 established (server 
localhost:443)
[Tue Feb 02 01:51:56.674340 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[874b6d8] in: flush 873dd50
[Tue Feb 02 01:51:56.674364 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[873dd50] out: FLUSH
[Tue Feb 02 01:51:56.674405 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[874b6d8] in: read 11bytes
[Tue Feb 02 01:51:56.674425 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[874b6d8] in: flush 873dd50
[Tue Feb 02 01:51:56.674432 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[873dd50] out: FLUSH
[Tue Feb 02 01:51:56.674440 2016] [ssl:notice] [pid 2680] [client 
XXX.XXX.XXX.XXX:47826] bio[874b6d8] in: read 156bytes
[Tue Feb 02 01:51:56.674480 2016] [ssl:debug] [pid 2680] 
ssl_engine_kernel.c(2103): [client XXX.XXX.XXX.XXX:47826] AH02044: No matching 
SSL virtual host for servername na171 found (using default/first virtual host)

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

On 2016-02-01 4:19, Yann Ylavic wrote:

This restores the previous (pre 2.4.18) behaviour of flushing output
on every read, which I'd prefer to avoid, if possible.

Could you provide some network capture (tcpdump, wireshark...) when
the lock-up occurs?


I'll work on capturing this, in the meantime I tried your patch below.


Is EnableMMap somehow always involded here (you mention it in the
original message)?


I had mentioned this because we have some requests passed through a 
custom handler, not serviced from the filesystem, and these never seem 
to exhibit the problem. All the failing requests I've debugged were 
serviced by Apache itself directly from the filesystem, and Apache used 
mmap for this. I can try disabling mmap to see if the problem goes away.



That would help to build a reproducer...

Maybe the attached patch could be "enough" to fix the issue?


It does not. The behaviour is exactly as with the original 2.4.18 
version. Note, that the problem is reproduced consistently. Requests 
that get stuck always get stuck every time I try to repeat it. If this 
was somehow related to renegotiation, would it not be more variable?



This patch also includes some minimal logging (level NOTICE) to help
diagnose in case of lock-up, still.


The log output for a failing request is attached.

Thanks,

Joachim

--
joac...@kraut.ca http://www.kraut.ca
[Mon Feb 01 12:30:12.289534 2016] [ssl:info] [pid 2436] [client 
205.159.216.185:47084] AH01964: Connection to child 0 established (server 
localhost:443)
[Mon Feb 01 12:30:12.289915 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.290009 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.290058 2016] [ssl:debug] [pid 2436] 
ssl_engine_kernel.c(2103): [client 205.159.216.185:47084] AH02044: No matching 
SSL virtual host for servername na171 found (using default/first virtual host)
[Mon Feb 01 12:30:12.295817 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] out: passing 1004 bytes
[Mon Feb 01 12:30:12.295897 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.300456 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302417 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302429 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302542 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302554 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302656 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] out: passing 51 bytes
[Mon Feb 01 12:30:12.302757 2016] [socache_shmcb:debug] [pid 2436] 
mod_socache_shmcb.c(491): AH00831: socache_shmcb_store (0x9e -> subcache 30)
[Mon Feb 01 12:30:12.302775 2016] [socache_shmcb:debug] [pid 2436] 
mod_socache_shmcb.c(845): AH00847: insert happened at idx=0, data=(0:32)
[Mon Feb 01 12:30:12.302782 2016] [socache_shmcb:debug] [pid 2436] 
mod_socache_shmcb.c(850): AH00848: finished insert, subcache: 
idx_pos/idx_used=0/1, data_pos/data_used=0/189
[Mon Feb 01 12:30:12.302838 2016] [socache_shmcb:debug] [pid 2436] 
mod_socache_shmcb.c(512): AH00834: leaving socache_shmcb_store successfully
[Mon Feb 01 12:30:12.302883 2016] [ssl:debug] [pid 2436] 
ssl_engine_kernel.c(2023): [client 205.159.216.185:47084] AH02041: Protocol: 
TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
[Mon Feb 01 12:30:12.302938 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.303955 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.304074 2016] [ssl:debug] [pid 2436] 
ssl_engine_kernel.c(354): [client 205.159.216.185:47084] AH02034: Initial 
(No.1) HTTPS request received for child 0 (server localhost:443)
[Mon Feb 01 12:30:12.304248 2016] [authz_core:debug] [pid 2436] 
mod_authz_core.c(809): [client 205.159.216.185:47084] AH01626: authorization 
result of Require all granted: granted
[Mon Feb 01 12:30:12.304259 2016] [authz_core:debug] [pid 2436] 
mod_authz_core.c(809): [client 205.159.216.185:47084] AH01626: authorization 
result of : granted
[Mon Feb 01 12:30:12.304398 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] out: passing 271 bytes
[Mon Feb 01 12:30:12.304509 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] out: passing 1727 bytes
[Mon Feb 01 12:30:12.304568 2016] [ssl:notice] [pid 2436] [client 
205.159.216.185:47084] bio[9813d50] in: not flushing

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

The Wireshark trace confirms what one may have predicted from the
observed symptoms. There is no response from the server to the GET
request on the wire. The pcap file and dissected text file were sent to
Yann privately.

I've now also tried with "EnableMMAP Off" and this makes no difference.

The problem does not occur for all files. I have not done an exhaustive
test with all our static files, but it seems that the problem
occurs primarily with small files. For example, these two files cause
the lock-up:

  -rw-rw-r-- 1 root naadmin 2509 Jan 19 14:10 css/home_styles.css
  -rw-rw-r-- 1 root naadmin 1698 Jan 19 14:10 css/subpage.css

These three files work fine:

  -rw-rw-r-- 1 root naadmin 6478 Jan 19 14:10 css/application.css
  -rw-rw-r-- 1 root naadmin 3991 Jan 19 14:10 css/homepage.css
  -rw-rw-r-- 1 root naadmin 1239621 Jan 19 14:10 jar/jconfig.jar

Joachim


On 2016-02-01 12:34, Joachim Achtzehnter wrote:

On 2016-02-01 4:19, Yann Ylavic wrote:

This restores the previous (pre 2.4.18) behaviour of flushing
output on every read, which I'd prefer to avoid, if possible.

Could you provide some network capture (tcpdump, wireshark...) when
the lock-up occurs?


I'll work on capturing this, in the meantime I tried your patch
below.


Is EnableMMap somehow always involded here (you mention it in the
original message)?


I had mentioned this because we have some requests passed through a
custom handler, not serviced from the filesystem, and these never
seem to exhibit the problem. All the failing requests I've debugged
were serviced by Apache itself directly from the filesystem, and
Apache used mmap for this. I can try disabling mmap to see if the
problem goes away.


That would help to build a reproducer...

Maybe the attached patch could be "enough" to fix the issue?


It does not. The behaviour is exactly as with the original 2.4.18
version. Note, that the problem is reproduced consistently. Requests
that get stuck always get stuck every time I try to repeat it. If
this was somehow related to renegotiation, would it not be more
variable?


This patch also includes some minimal logging (level NOTICE) to
help diagnose in case of lock-up, still.


The log output for a failing request is attached.

Thanks,

Joachim



--
joac...@kraut.ca http://www.kraut.ca

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Mon, Feb 1, 2016 at 3:41 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
> After upgrading from 2.4.12 to 2.4.18 we find that some requests for files
> cause a lock-up when HTTPS is used, but not with plain HTTP. After some
> debugging it seems the problem is that the mod_ssl no longer explicitly
> flushes the output it produced before going back to reading a new request on
> the same connection.
>
> This is a 32-bit Intel Linux platform, and by stepping through the mod_ssl
> output filter in the debugger I can see that the files that cause problems
> are being read by Apache using the mmap approach.
>
> Restoring the explicit flushing from 2.4.12 gets the 2.4.18 version of
> mod-ssl working for us. Here is the patch:

Which system and openssl versions are you using?
Did you build 2.4.18 yourself, against the same version of openssl the
system is running?

Regards,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

The problem was first discovered with Apache 2.4.18 compiled against 
OpenSSL/1.0.1m. The running system, which is an i686 Linux system, used 
the same versions.


We then installed our old mod_ssl.so from Apache 2.4.12, everything else 
unchanged, and this worked. This was enough of a hint to debug the 
2.4.18 version of the module. Before doing this, we downloaded the 
latest apr/apr-util, and OpenSSL packages, and rebuilt everything. 
OpenSSL is now at 1.0.2f. All of this was installed on the running 
system, and it behaved the same way, with some files causing the client 
to hang forever.


Applying the patch I included in the previous message gets it working 
for us.


Joachim


On 2016-02-01 12:06 AM, Yann Ylavic wrote:

On Mon, Feb 1, 2016 at 3:41 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:

After upgrading from 2.4.12 to 2.4.18 we find that some requests for files
cause a lock-up when HTTPS is used, but not with plain HTTP. After some
debugging it seems the problem is that the mod_ssl no longer explicitly
flushes the output it produced before going back to reading a new request on
the same connection.

This is a 32-bit Intel Linux platform, and by stepping through the mod_ssl
output filter in the debugger I can see that the files that cause problems
are being read by Apache using the mmap approach.

Restoring the explicit flushing from 2.4.12 gets the 2.4.18 version of
mod-ssl working for us. Here is the patch:


Which system and openssl versions are you using?
Did you build 2.4.18 yourself, against the same version of openssl the
system is running?

Regards,
Yann.



--
joac...@kraut.ca   www.kraut.ca

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

A little precision:

On Mon, Feb 1, 2016 at 1:19 PM, Yann Ylavic  wrote:
>
> Could you provide some network capture (tcpdump, wireshark...) when
> the lock-up occurs?

I mean a pcap format here, the goal is correlating with the SSL
handshake (or renegotiation) which should be the only times where we
need to flush output.
It could be hard to parse the handshake with a simple text capture...

You may send it to me privately if it's a concern.

Thanks,
Yann.

Re: HTTPS connections lock-up with 2.4.18

[Jim Jagielski]

Looks like this is "fallout" from:

http://svn.apache.org/viewvc?view=revision=1707230


> On Jan 31, 2016, at 9:41 PM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
> 
> After upgrading from 2.4.12 to 2.4.18 we find that some requests for files 
> cause a lock-up when HTTPS is used, but not with plain HTTP. After some 
> debugging it seems the problem is that the mod_ssl no longer explicitly 
> flushes the output it produced before going back to reading a new request on 
> the same connection.
> 
> This is a 32-bit Intel Linux platform, and by stepping through the mod_ssl 
> output filter in the debugger I can see that the files that cause problems 
> are being read by Apache using the mmap approach.
> 
> Restoring the explicit flushing from 2.4.12 gets the 2.4.18 version of 
> mod-ssl working for us. Here is the patch:
> 
> 
> --- ssl_engine_io.c.orig  2015-11-19 11:55:25.0 -0800
> +++ ssl_engine_io.c   2016-01-31 17:22:54.586227441 -0800
> @@ -466,6 +466,21 @@
> return -1;
> }
> 
> +/* In theory, OpenSSL should flush as necessary, but it is known
> + * not to do so correctly in some cases; see PR 46952.
> + *
> + * Historically, this flush call was performed only for an SSLv2
> + * connection or for a proxy connection.  Calling _out_flush
> + * should be very cheap in cases where it is unnecessary (and no
> + * output is buffered) so the performance impact of doing it
> + * unconditionally should be minimal.
> + */
> +if (bio_filter_out_flush(inctx->bio_out) < 0) {
> +bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
> +inctx->rc = outctx->rc;
> +return -1;
> +}
> +
> BIO_clear_retry_flags(bio);
> 
> if (!inctx->bb) {
> 
> 
> 

Re: HTTPS connections lock-up with 2.4.18

[Yann Ylavic]

On Mon, Feb 1, 2016 at 10:10 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:
> The problem was first discovered with Apache 2.4.18 compiled against
> OpenSSL/1.0.1m. The running system, which is an i686 Linux system, used the
> same versions.
>
> We then installed our old mod_ssl.so from Apache 2.4.12, everything else
> unchanged, and this worked. This was enough of a hint to debug the 2.4.18
> version of the module. Before doing this, we downloaded the latest
> apr/apr-util, and OpenSSL packages, and rebuilt everything. OpenSSL is now
> at 1.0.2f. All of this was installed on the running system, and it behaved
> the same way, with some files causing the client to hang forever.

Thanks for the details.

>
> Applying the patch I included in the previous message gets it working for
> us.

This restores the previous (pre 2.4.18) behaviour of flushing output
on every read, which I'd prefer to avoid, if possible.

Could you provide some network capture (tcpdump, wireshark...) when
the lock-up occurs?
Is EnableMMap somehow always involded here (you mention it in the
original message)?
That would help to build a reproducer...

Maybe the attached patch could be "enough" to fix the issue?
This patch also includes some minimal logging (level NOTICE) to help
diagnose in case of lock-up, still.
It may be necessary to apply patch [1] before (conflict with current
2.4.x, which the attached patch is based on).

Regards,
Yann.

[1] 
http://svn.apache.org/viewvc/httpd/httpd/branches/2.4.x/modules/ssl/ssl_engine_io.c?r1=1722179=1722178=1722179=patch
Index: modules/ssl/ssl_engine_io.c
===
--- modules/ssl/ssl_engine_io.c	(revision 1727923)
+++ modules/ssl/ssl_engine_io.c	(working copy)
@@ -183,11 +183,19 @@ static int bio_filter_out_read(BIO *bio, char *out
 return -1;
 }
 
+static int modssl_ssl_need_flush(SSL *ssl)
+{
+#if OPENSSL_VERSION_NUMBER < 0x0009080df
+ return !SSL_is_init_finished(ssl);
+#else
+ return SSL_in_connect_init(ssl);
+#endif
+}
+
 static int bio_filter_out_write(BIO *bio, const char *in, int inl)
 {
 bio_filter_out_ctx_t *outctx = (bio_filter_out_ctx_t *)(bio->ptr);
 apr_bucket *e;
-int need_flush;
 
 /* Abort early if the client has initiated a renegotiation. */
 if (outctx->filter_ctx->config->reneg_state == RENEG_ABORT) {
@@ -210,24 +218,20 @@ static int bio_filter_out_write(BIO *bio, const ch
  * not to do so correctly in some cases (< 0.9.8m; see PR 46952),
  * or on the proxy/client side (after ssl23_client_hello(), e.g.
  * ssl/proxy.t test suite).
- *
- * Historically, this flush call was performed only for an SSLv2
- * connection or for a proxy connection.  Calling _out_flush can
- * be expensive in cases where requests/reponses are pipelined,
- * so limit the performance impact to handshake time.
  */
-#if OPENSSL_VERSION_NUMBER < 0x0009080df
- need_flush = !SSL_is_init_finished(outctx->filter_ctx->pssl);
-#else
- need_flush = SSL_in_connect_init(outctx->filter_ctx->pssl);
-#endif
-if (need_flush) {
-e = apr_bucket_flush_create(outctx->bb->bucket_alloc);
-APR_BRIGADE_INSERT_TAIL(outctx->bb, e);
+if (!modssl_ssl_need_flush(outctx->filter_ctx->pssl)) {
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] out: passing %d bytes", bio, inl);
+if (bio_filter_out_pass(outctx) < 0) {
+return -1;
+}
 }
-
-if (bio_filter_out_pass(outctx) < 0) {
-return -1;
+else {
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] out: flushing %d bytes", bio, inl);
+if (bio_filter_out_flush(bio) < 0) {
+return -1;
+}
 }
 
 return inl;
@@ -468,6 +472,31 @@ static int bio_filter_in_read(BIO *bio, char *in,
 
 BIO_clear_retry_flags(bio);
 
+/* In theory, OpenSSL should flush as necessary, but it is known
+ * not to do so correctly in some cases (< 0.9.8m; see PR 46952),
+ * or on the proxy/client side (after ssl23_client_hello(), e.g.
+ * ssl/proxy.t test suite).
+ *
+ * Historically, this flush call was performed only for an SSLv2
+ * connection or for a proxy connection.  Calling _out_flush can
+ * be expensive in cases where requests/reponses are pipelined,
+ * so limit the performance impact to handshake time.
+ */
+if (modssl_ssl_need_flush(inctx->filter_ctx->pssl)) {
+bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
+ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+  "bio[%pp] in: flushing", inctx->bio_out);
+if (bio_filter_out_flush(inctx->bio_out) < 0) {
+inctx->rc = outctx-

HTTPS connections lock-up with 2.4.18

[Joachim Achtzehnter]

After upgrading from 2.4.12 to 2.4.18 we find that some requests for 
files cause a lock-up when HTTPS is used, but not with plain HTTP. After 
some debugging it seems the problem is that the mod_ssl no longer 
explicitly flushes the output it produced before going back to reading a 
new request on the same connection.


This is a 32-bit Intel Linux platform, and by stepping through the 
mod_ssl output filter in the debugger I can see that the files that 
cause problems are being read by Apache using the mmap approach.


Restoring the explicit flushing from 2.4.12 gets the 2.4.18 version of 
mod-ssl working for us. Here is the patch:



--- ssl_engine_io.c.orig2015-11-19 11:55:25.0 -0800
+++ ssl_engine_io.c 2016-01-31 17:22:54.586227441 -0800
@@ -466,6 +466,21 @@
 return -1;
 }

+/* In theory, OpenSSL should flush as necessary, but it is known
+ * not to do so correctly in some cases; see PR 46952.
+ *
+ * Historically, this flush call was performed only for an SSLv2
+ * connection or for a proxy connection.  Calling _out_flush
+ * should be very cheap in cases where it is unnecessary (and no
+ * output is buffered) so the performance impact of doing it
+ * unconditionally should be minimal.
+ */
+if (bio_filter_out_flush(inctx->bio_out) < 0) {
+bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
+inctx->rc = outctx->rc;
+return -1;
+}
+
 BIO_clear_retry_flags(bio);

 if (!inctx->bb) {

Re: [ANNOUNCEMENT] Apache HTTP Server 2.4.18 Released

[Jim Jagielski]

It was sent to both announce@a.o as well as announce@h.a.o

And sent w/ my jim@a.o address, as required.
> On Dec 22, 2015, at 11:32 AM, Rainer Jung <rainer.j...@kippdata.de> wrote:
> 
> It looks like the announcement never made it to the ASF accouncement list? 
> The same was true for 2.4.17 but 2.4.16 was announced on that list too.
> 
> Does it make sense to send the announcement there. Of course it has a unusual 
> delay now but some people might rely on that channel for the info.
> 
> Regards,
> 
> Rainer
> 
> Am 14.12.2015 um 21:09 schrieb Jim Jagielski:
>> Apache HTTP Server 2.4.18 Released
>> 
>> The Apache Software Foundation and the Apache HTTP Server Project
>> are pleased to announce the release of version 2.4.18 of the Apache
>> HTTP Server ("Apache").  This version of Apache is our latest GA
>> release of the new generation 2.4.x branch of Apache HTTPD and
>> represents fifteen years of innovation by the project, and is
>> recommended over all previous releases. This release of Apache is
>> principally a feature and bug fix release.
>> 
>> We consider this release to be the best version of Apache available, and
>> encourage users of all prior versions to upgrade.
>> 
>> Apache HTTP Server 2.4.18 is available for download from:
>> 
>>  http://httpd.apache.org/download.cgi
>> 
>> Apache 2.4 offers numerous enhancements, improvements, and performance
>> boosts over the 2.2 codebase.  For an overview of new features
>> introduced since 2.4 please see:
>> 
>>  http://httpd.apache.org/docs/trunk/new_features_2_4.html
>> 
>> Please see the CHANGES_2.4 file, linked from the download page, for a
>> full list of changes. A condensed list, CHANGES_2.4.18 includes only
>> those changes introduced since the prior 2.4 release.  A summary of all
>> of the security vulnerabilities addressed in this and earlier releases
>> is available:
>> 
>>  http://httpd.apache.org/security/vulnerabilities_24.html
>> 
>> This release requires the Apache Portable Runtime (APR) version 1.5.x
>> and APR-Util version 1.5.x. The APR libraries must be upgraded for all
>> features of httpd to operate correctly.
>> 
>> This release builds on and extends the Apache 2.2 API.  Modules written
>> for Apache 2.2 will need to be recompiled in order to run with Apache
>> 2.4, and require minimal or no source code changes.
>> 
>>  http://svn.apache.org/repos/asf/httpd/httpd/trunk/VERSIONING
>> 
>> When upgrading or installing this version of Apache, please bear in mind
>> that if you intend to use Apache with one of the threaded MPMs (other
>> than the Prefork MPM), you must ensure that any modules you will be
>> using (and the libraries they depend on) are thread-safe.

Re: [ANNOUNCEMENT] Apache HTTP Server 2.4.18 Released

[William A Rowe Jr]

All a@a.o must be moderated (from non-@apache addresses it hits
the bit bucket).  Enjoying some time with kids and dealing with only
critical work email so this one escaped my attention, but if another
ASF member wanted to moderate, volunteers are always welcome.
Usually I catch these within the hour, but not always.



On Tue, Dec 22, 2015 at 3:02 PM, Jim Jagielski <j...@jagunet.com> wrote:

> It was sent to both announce@a.o as well as announce@h.a.o
>
> And sent w/ my jim@a.o address, as required.
> > On Dec 22, 2015, at 11:32 AM, Rainer Jung <rainer.j...@kippdata.de>
> wrote:
> >
> > It looks like the announcement never made it to the ASF accouncement
> list? The same was true for 2.4.17 but 2.4.16 was announced on that list
> too.
> >
> > Does it make sense to send the announcement there. Of course it has a
> unusual delay now but some people might rely on that channel for the info.
> >
> > Regards,
> >
> > Rainer
> >
> > Am 14.12.2015 um 21:09 schrieb Jim Jagielski:
> >> Apache HTTP Server 2.4.18 Released
> >>
> >> The Apache Software Foundation and the Apache HTTP Server Project
> >> are pleased to announce the release of version 2.4.18 of the Apache
> >> HTTP Server ("Apache").  This version of Apache is our latest GA
> >> release of the new generation 2.4.x branch of Apache HTTPD and
> >> represents fifteen years of innovation by the project, and is
> >> recommended over all previous releases. This release of Apache is
> >> principally a feature and bug fix release.
> >>
> >> We consider this release to be the best version of Apache available, and
> >> encourage users of all prior versions to upgrade.
> >>
> >> Apache HTTP Server 2.4.18 is available for download from:
> >>
> >>  http://httpd.apache.org/download.cgi
> >>
> >> Apache 2.4 offers numerous enhancements, improvements, and performance
> >> boosts over the 2.2 codebase.  For an overview of new features
> >> introduced since 2.4 please see:
> >>
> >>  http://httpd.apache.org/docs/trunk/new_features_2_4.html
> >>
> >> Please see the CHANGES_2.4 file, linked from the download page, for a
> >> full list of changes. A condensed list, CHANGES_2.4.18 includes only
> >> those changes introduced since the prior 2.4 release.  A summary of all
> >> of the security vulnerabilities addressed in this and earlier releases
> >> is available:
> >>
> >>  http://httpd.apache.org/security/vulnerabilities_24.html
> >>
> >> This release requires the Apache Portable Runtime (APR) version 1.5.x
> >> and APR-Util version 1.5.x. The APR libraries must be upgraded for all
> >> features of httpd to operate correctly.
> >>
> >> This release builds on and extends the Apache 2.2 API.  Modules written
> >> for Apache 2.2 will need to be recompiled in order to run with Apache
> >> 2.4, and require minimal or no source code changes.
> >>
> >>  http://svn.apache.org/repos/asf/httpd/httpd/trunk/VERSIONING
> >>
> >> When upgrading or installing this version of Apache, please bear in mind
> >> that if you intend to use Apache with one of the threaded MPMs (other
> >> than the Prefork MPM), you must ensure that any modules you will be
> >> using (and the libraries they depend on) are thread-safe.
>
>

Bugzilla has no version 2.4.18

[Daniil Iaitskov]

Hi,


-- 


Daneel Yaitskov

Re: Bugzilla has no version 2.4.18

[Rainer Jung]

Done, thanks for the reminder.

Rainer

Re: [ANNOUNCEMENT] Apache HTTP Server 2.4.18 Released

[Rainer Jung]

It looks like the announcement never made it to the ASF accouncement 
list? The same was true for 2.4.17 but 2.4.16 was announced on that list 
too.


Does it make sense to send the announcement there. Of course it has a 
unusual delay now but some people might rely on that channel for the info.


Regards,

Rainer

Am 14.12.2015 um 21:09 schrieb Jim Jagielski:

 Apache HTTP Server 2.4.18 Released

The Apache Software Foundation and the Apache HTTP Server Project
are pleased to announce the release of version 2.4.18 of the Apache
HTTP Server ("Apache").  This version of Apache is our latest GA
release of the new generation 2.4.x branch of Apache HTTPD and
represents fifteen years of innovation by the project, and is
recommended over all previous releases. This release of Apache is
principally a feature and bug fix release.

We consider this release to be the best version of Apache available, and
encourage users of all prior versions to upgrade.

Apache HTTP Server 2.4.18 is available for download from:

  http://httpd.apache.org/download.cgi

Apache 2.4 offers numerous enhancements, improvements, and performance
boosts over the 2.2 codebase.  For an overview of new features
introduced since 2.4 please see:

  http://httpd.apache.org/docs/trunk/new_features_2_4.html

Please see the CHANGES_2.4 file, linked from the download page, for a
full list of changes. A condensed list, CHANGES_2.4.18 includes only
those changes introduced since the prior 2.4 release.  A summary of all
of the security vulnerabilities addressed in this and earlier releases
is available:

  http://httpd.apache.org/security/vulnerabilities_24.html

This release requires the Apache Portable Runtime (APR) version 1.5.x
and APR-Util version 1.5.x. The APR libraries must be upgraded for all
features of httpd to operate correctly.

This release builds on and extends the Apache 2.2 API.  Modules written
for Apache 2.2 will need to be recompiled in order to run with Apache
2.4, and require minimal or no source code changes.

  http://svn.apache.org/repos/asf/httpd/httpd/trunk/VERSIONING

When upgrading or installing this version of Apache, please bear in mind
that if you intend to use Apache with one of the threaded MPMs (other
than the Prefork MPM), you must ensure that any modules you will be
using (and the libraries they depend on) are thread-safe.

Re: [RESULT] Was: [VOTE] Release Apache httpd 2.4.18 as GA

[Stefan Eissing]

Thanks for RMing, Jim!

> Am 11.12.2015 um 23:23 schrieb Jim Jagielski <j...@jagunet.com>:
> 
> With more than the required 3 +1 (binding) votes, I call
> the VOTE closed with the result that the VOTE PASSES.
> 
> I will start moving the artifacts so the mirrors can collect
> them over the weekend.
> 
>> On Dec 8, 2015, at 3:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
>> 
>> The pre-release test tarballs for Apache httpd 2.4.18 can be found
>> at the usual place:
>> 
>>  http://httpd.apache.org/dev/dist/
>> 
>> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
>> 
>> [ ] +1: Good to go
>> [ ] +0: meh
>> [ ] -1: Danger Will Robinson. And why.
>> 
>> Vote will last the normal 72 hrs.
>> 
>> NOTE: The *-deps are only there for convenience.
>> 
>> Thx!
> 

[ANNOUNCEMENT] Apache HTTP Server 2.4.18 Released

[Jim Jagielski]

Apache HTTP Server 2.4.18 Released

The Apache Software Foundation and the Apache HTTP Server Project
are pleased to announce the release of version 2.4.18 of the Apache
HTTP Server ("Apache").  This version of Apache is our latest GA
release of the new generation 2.4.x branch of Apache HTTPD and
represents fifteen years of innovation by the project, and is
recommended over all previous releases. This release of Apache is
principally a feature and bug fix release.

We consider this release to be the best version of Apache available, and
encourage users of all prior versions to upgrade.

Apache HTTP Server 2.4.18 is available for download from:

 http://httpd.apache.org/download.cgi

Apache 2.4 offers numerous enhancements, improvements, and performance
boosts over the 2.2 codebase.  For an overview of new features
introduced since 2.4 please see:

 http://httpd.apache.org/docs/trunk/new_features_2_4.html

Please see the CHANGES_2.4 file, linked from the download page, for a
full list of changes. A condensed list, CHANGES_2.4.18 includes only
those changes introduced since the prior 2.4 release.  A summary of all 
of the security vulnerabilities addressed in this and earlier releases 
is available:

 http://httpd.apache.org/security/vulnerabilities_24.html

This release requires the Apache Portable Runtime (APR) version 1.5.x
and APR-Util version 1.5.x. The APR libraries must be upgraded for all
features of httpd to operate correctly.

This release builds on and extends the Apache 2.2 API.  Modules written
for Apache 2.2 will need to be recompiled in order to run with Apache
2.4, and require minimal or no source code changes.

 http://svn.apache.org/repos/asf/httpd/httpd/trunk/VERSIONING

When upgrading or installing this version of Apache, please bear in mind
that if you intend to use Apache with one of the threaded MPMs (other
than the Prefork MPM), you must ensure that any modules you will be
using (and the libraries they depend on) are thread-safe.

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Yann Ylavic]

On Tue, Dec 8, 2015 at 9:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
>
> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
>
> [X] +1: Good to go

md5/sha1/pgp OK

Tested on:

* Debian 8.2 (Jessie)
=> All tests passed.

* Debian 7.9 (Wheezy)
=> All tests passed.

* Debian 6.0.10 (Squeeze)
=> No regression.

Thanks Jim from RMing.

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Gregg Smith]

+1 Various flavors of VC/Windows


On 12/8/2015 12:38 PM, Jim Jagielski wrote:

The pre-release test tarballs for Apache httpd 2.4.18 can be found
at the usual place:

http://httpd.apache.org/dev/dist/

I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

[ ] +1: Good to go
[ ] +0: meh
[ ] -1: Danger Will Robinson. And why.

Vote will last the normal 72 hrs.

NOTE: The *-deps are only there for convenience.

Thx!

[RESULT] Was: [VOTE] Release Apache httpd 2.4.18 as GA

[Jim Jagielski]

With more than the required 3 +1 (binding) votes, I call
the VOTE closed with the result that the VOTE PASSES.

I will start moving the artifacts so the mirrors can collect
them over the weekend.

> On Dec 8, 2015, at 3:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
> 
> The pre-release test tarballs for Apache httpd 2.4.18 can be found
> at the usual place:
> 
>   http://httpd.apache.org/dev/dist/
> 
> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
> 
> [ ] +1: Good to go
> [ ] +0: meh
> [ ] -1: Danger Will Robinson. And why.
> 
> Vote will last the normal 72 hrs.
> 
> NOTE: The *-deps are only there for convenience.
> 
> Thx!

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Yann Ylavic]

On Fri, Dec 11, 2015 at 9:21 PM, Rainer Jung  wrote:
>
>   - three compiler warning (2 regressions, one old)
[]
>   modules/ssl/ssl_engine_kernel.c:414:22: warning: variable 'hssc' set
> but not used [-Wunused-but-set-variable]

This one is harmless ('hssc' redeclared and used below in inner scope).
But I checked twice since handshakeserver (there) is not checked
against NULL like at the initialization.
Fortunately the !ssl path above handles the case, so this is simply a
double initialization (to the same value), likely optimized away
finally...

-Wunused-but-set-variable does its job, though.

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Yann Ylavic]

On Fri, Dec 11, 2015 at 10:57 PM, Yann Ylavic <ylavic@gmail.com> wrote:
> On Fri, Dec 11, 2015 at 10:39 PM, Yann Ylavic <ylavic@gmail.com> wrote:
>> On Fri, Dec 11, 2015 at 9:21 PM, Rainer Jung <rainer.j...@kippdata.de> wrote:
>>>
>>>   - three compiler warning (2 regressions, one old)
>> []
>>>   modules/ssl/ssl_engine_kernel.c:414:22: warning: variable 'hssc' set
>>> but not used [-Wunused-but-set-variable]
>>
>> This one is harmless ('hssc' redeclared and used below in inner scope).
>> But I checked twice since handshakeserver (there) is not checked
>> against NULL like at the initialization.
>> Fortunately the !ssl path above handles the case, so this is simply a
>> double initialization (to the same value), likely optimized away
>> finally...
>>
>> -Wunused-but-set-variable does its job, though.
>
> The original commit in trunk (r1709995) contained:
> @@ -529,7 +672,6 @@ int ssl_hook_Access(request_rec *r)
>   */
>  if ((dc->nVerifyClient != SSL_CVERIFY_UNSET) ||
>  (sc->server->auth.verify_mode != SSL_CVERIFY_UNSET)) {
> -SSLSrvConfigRec *hssc = mySrvConfig(handshakeserver);
>
>  /* remember old state */
>  verify_old = SSL_get_verify_mode(ssl);
> --

This turned into (r1712567, 2.4.17-protocols-changes):
@@ -554,6 +697,7 @@ int ssl_hook_Access(request_rec *r)
  */
 if ((dc->nVerifyClient != SSL_CVERIFY_UNSET) ||
 (sc->server->auth.verify_mode != SSL_CVERIFY_UNSET)) {
+
 /* remember old state */
 verify_old = SSL_get_verify_mode(ssl);
     /* configure new state */
--
which was then merged in 2.4.x.

This is the only change which "failed" in r1712567, and trunk and
2.4.x are in sync wrt the changes in 2.4.18, so finally not an issue.

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Yann Ylavic]

On Fri, Dec 11, 2015 at 10:39 PM, Yann Ylavic  wrote:
> On Fri, Dec 11, 2015 at 9:21 PM, Rainer Jung  wrote:
>>
>>   - three compiler warning (2 regressions, one old)
> []
>>   modules/ssl/ssl_engine_kernel.c:414:22: warning: variable 'hssc' set
>> but not used [-Wunused-but-set-variable]
>
> This one is harmless ('hssc' redeclared and used below in inner scope).
> But I checked twice since handshakeserver (there) is not checked
> against NULL like at the initialization.
> Fortunately the !ssl path above handles the case, so this is simply a
> double initialization (to the same value), likely optimized away
> finally...
>
> -Wunused-but-set-variable does its job, though.

The original commit in trunk (r1709995) contained:
@@ -529,7 +672,6 @@ int ssl_hook_Access(request_rec *r)
  */
 if ((dc->nVerifyClient != SSL_CVERIFY_UNSET) ||
 (sc->server->auth.verify_mode != SSL_CVERIFY_UNSET)) {
-SSLSrvConfigRec *hssc = mySrvConfig(handshakeserver);

 /* remember old state */
 verify_old = SSL_get_verify_mode(ssl);
--

But somehow the merge in 2.4.x (r1715255, from
2.4.17-protocols-changes branch?) does not.

Looks like a merge issue :/
Comparing files now...

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Rainer Canavan]

2015-12-11 19:59 GMT+01:00 Jim Jagielski :
> Just a quick reminder that the voting closes in about 90mins.
>
> tia!

builds and works according to my casual tests on IRIX mips as n32.

rainer

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Rainer Jung]

Am 08.12.2015 um 21:38 schrieb Jim Jagielski:

The pre-release test tarballs for Apache httpd 2.4.18 can be found
at the usual place:

http://httpd.apache.org/dev/dist/

I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

[X] +1: Good to go
[ ] +0: meh
[ ] -1: Danger Will Robinson. And why.

Vote will last the normal 72 hrs.


+1 to release and thank a bunch for RMing.

In short: No regressions found.

Detailed report:

- Sigs and hashes OK
- contents of tarballs identical
- contents of tag and tarballs identical
  except for expected deltas
  (we could cleanup some m4 files in apr-util/xml/expat/conftools
   at the end of buildconf, no regression)

Built on

- Solaris 8+10 Sparc as 32 Bit Binaries
- SLES 10+11 (64 Bits)
- RHEL 6 (64 Bits)

For all platforms built

- with default (shared), shared and static modules
- with module sets none, few, most, all, reallyall and default
  (always mod_privileges disabled)
- using --enable-load-all-modules
- against "included" APR/APU from deps tarball,
  plus external APR/APU 1.5.2/1.5.4

- using external libraries
  - expat 2.1.0 plus patch
  - pcre 8.37
  - openssl 1.0.2e
  - lua 5.2.4
  - distcache 1.5.1
  - libxml2 2.9.3
  - libnghttp2 1.5.0

- Tool chain:
- platform gcc except for Solaris
  (gcc 4.4.4 for Solaris 8 and 4.9.2 for Solaris 10)
- CFLAGS: -O2 -g -Wall -fno-strict-aliasing
  (and -mpcu=v9 on Solaris)

All builds succeeded
  - three compiler warning (2 regressions, one old)
  modules/http2/h2_conn_io.c:401:2: warning: no newline at end of file
  modules/ssl/ssl_engine_kernel.c:414:22: warning: variable 'hssc' 
set but not used [-Wunused-but-set-variable]
  modules/ssl/ssl_util_stapling.c:686: warning: 'ok' may be used 
uninitialized in this function


Tested for

- 343 build combinations
- Solaris 8+10 (32), SLES 10+11 (64), RHEL 6 (64)
- MPMs prefork, worker, event
  (except event on Solaris8, unsupported)
- default, shared and static modules
- log levels info, debug and trace8
- module set reallyall (122 modules plus MPMs)
- SLES 10 and RHEL 6 still ongoing but so far OK

The tests sometimes produce perl warnings:

- Use of uninitialized value in length at
  .../lib/perl5/Protocol/HTTP2/Stream.pm line 366.
  Printed at the start of the http2 test runs.
  Only on the Linux platform.

- Status read failed: at
  .../lib/perl5/Net/HTTP/Methods.pm line 289.
  Printed for test 1 and 3 of t/ssl/verify.t

The following test failures were seen:

a Test 4 or 5 in t/modules/dav.t:
  Happens for 37 out of 343 runs (14 on SLES 10, 13 on SLES 11,
  7 on RHEL 6, 2 on Solaris 8, 1 on Solaris 10).
  Creation, modified and now times not in the correct order.
  This seems to be a system issue, all tests done on NFS,
  many tested on virtualized guests.
  Not a regression.

b Various tests in t/apache/expr_string.t: (6, 11, 14, 17, 20 ,23)
  Happens for 50 out of 343 runs (45 on SLES 10, 3 on RHEL6,
  2 on Solaris 10).
  The failure is always on line 68, where the error_log contents
  are checked.
  Not a regression.

c Test 59 of t/modules/include.t only and always on
  Solaris.
  This is due to a bug in the test, which uses strftime()
  with a "%s" pattern that is not supported on Solaris.
  Until recently the server and the test client both returned
  verbatim "%s" and the test succeeded. After updating some
  Perl modules for the http2 tests, the perl client even
  on Solaris now supports "%s" in strftime and the test starts
  to fail. It seems we have to fix the test. Not a regression.

d Failure of t/modules/session.t on SLES 10.
  Warning: Use of "shift" without parentheses is ambiguous at line 39.
  Perl version is 5.8.8. The script uses a somewhat advances
  $x = shift // "NOTFOUND";
  construct, which seems to be ambiguous for old Perl (I had
  to look in the fine perl docs for the // operator).
  We could probably use a less elegant but more compatible
  construct instead. Not a regression.

e Failure of t/modules/http2.t: tests 11, 12, 15, 16, 45, 46
  Only 4 out of 343 runs fail, 3 on Solaris 8 one on RHEL 6.

  The failure always seems to be related with
  [cgid:error] End of script output before headers: necho.pl

Details for the 4 cases of http2 failures (I do have full logs incl. 
trace8 logs for two cases):


event-trace8-rhel6.x86_64-shared:

test case: TC0009, necho.pl without arguments: GET 
http://localhost:8544/modules/h2/necho.pl

# testing : response status
# expected: 400
# received: '500'
not ok 11
# testing : content comparision
# expected: '
# No query was specified.
# 
# '
# received: '
# 
# 500 Internal Server Error
# 
# Internal Server Error
# The server encountered an internal error or
# misconfiguration and was unable to complete
# your request.
# Please contact the server administrator at
#  y...@example.com to inform them of the time this error occurred,
#  and the actions you performed just before this

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Jim Jagielski]

Just a quick reminder that the voting closes in about 90mins.

tia!

> On Dec 8, 2015, at 3:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
> 
> The pre-release test tarballs for Apache httpd 2.4.18 can be found
> at the usual place:
> 
>   http://httpd.apache.org/dev/dist/
> 
> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
> 
> [ ] +1: Good to go
> [ ] +0: meh
> [ ] -1: Danger Will Robinson. And why.
> 
> Vote will last the normal 72 hrs.
> 
> NOTE: The *-deps are only there for convenience.
> 
> Thx!

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Steffen]

Running on AL for a few days, no issues/regressions seen on all the 
windows VC/OS flavors.


Also no crashes anymore with mod_http2 (discussed off-list with Stefan 
E)


Thanks dev's,

Steffen


On Tuesday 08/12/2015 at 21:38, Jim Jagielski  wrote:

The pre-release test tarballs for Apache httpd 2.4.18 can be found
at the usual place:

http://httpd.apache.org/dev/dist/

I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

[ ] +1: Good to go
[ ] +0: meh
[ ] -1: Danger Will Robinson. And why.

Vote will last the normal 72 hrs.

NOTE: The *-deps are only there for convenience.

Thx!

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Stefan Eissing]

+1: 14.04.1-Ubuntu SMP, gcc 4.8.4
worker, event, prefork

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Leif Hedstrom]

> On Dec 8, 2015, at 1:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
> 
> The pre-release test tarballs for Apache httpd 2.4.18 can be found
> at the usual place:
> 
>   http://httpd.apache.org/dev/dist/
> 
> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
> 
> [ ] +1: Good to go
> [ ] +0: meh
> [ ] -1: Danger Will Robinson. And why.
> 
> Vote will last the normal 72 hrs.


+1. Built, tested and run on Fedora 21 - 64-bit with PHP 5.6.4.

— leif

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Jim Jagielski]

+1:
 o OSX 10.11.2, Xcode 7.2: x64
 o CentOS6: x64
 o CentOS7: x64

> On Dec 8, 2015, at 3:38 PM, Jim Jagielski <j...@jagunet.com> wrote:
> 
> The pre-release test tarballs for Apache httpd 2.4.18 can be found
> at the usual place:
> 
>   http://httpd.apache.org/dev/dist/
> 
> I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
> 
> [ ] +1: Good to go
> [ ] +0: meh
> [ ] -1: Danger Will Robinson. And why.
> 
> Vote will last the normal 72 hrs.
> 
> NOTE: The *-deps are only there for convenience.
> 
> Thx!

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[William A Rowe Jr]

On Wed, Dec 9, 2015 at 1:02 PM, Jan Ehrhardt <php...@ehrhardt.nl> wrote:

> Jim Jagielski in gmane.comp.apache.devel (Tue, 8 Dec 2015 15:38:41 -0500):
> >The pre-release test tarballs for Apache httpd 2.4.18 can be found
> >at the usual place:
> >
> >   http://httpd.apache.org/dev/dist/
> >
> >I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.
>
> No idea who has voting rights, but I am
>
> +1 Build on Windows 7 Pro (VC9 / VC11 / VC14, x86 / x64)
>Tested on Windows 2008 R2 SP1
>

Everyone's votes are valued, whether they are 'weighed' or not!
Both positive and negative feedback from non-PMC members
strongly influence the RM and the PMC member's votes.

Thanks for testing :)

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Jan Ehrhardt]

Jim Jagielski in gmane.comp.apache.devel (Tue, 8 Dec 2015 15:38:41 -0500):
>The pre-release test tarballs for Apache httpd 2.4.18 can be found
>at the usual place:
>
>   http://httpd.apache.org/dev/dist/
>
>I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

No idea who has voting rights, but I am

+1 Build on Windows 7 Pro (VC9 / VC11 / VC14, x86 / x64)
   Tested on Windows 2008 R2 SP1
-- 
Jan

Re: [VOTE] Release Apache httpd 2.4.18 as GA

[Reindl Harald]

Am 08.12.2015 um 21:38 schrieb Jim Jagielski:

The pre-release test tarballs for Apache httpd 2.4.18 can be found
at the usual place:

http://httpd.apache.org/dev/dist/

I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

[ ] +1: Good to go
[ ] +0: meh
[ ] -1: Danger Will Robinson. And why.

Vote will last the normal 72 hrs


+1 Fedora 23 x86_64 with mod_security 2.9 and PHP 5.6.16
without HTTP2 part of the game the same most likely for Fedora 22



signature.asc
Description: OpenPGP digital signature

Re: 2.4.18 T

[Jim Jagielski]

This will be happening today, afternoon, eastern time.

Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Yann Ylavic]

On Tue, Dec 8, 2015 at 2:30 PM,   wrote:
> Author: ylavic
> Date: Tue Dec  8 13:30:30 2015
> New Revision: 1718595
>
> URL: http://svn.apache.org/viewvc?rev=1718595=rev
> Log:
> Comment about ap_request_has_body() check for Upgrade.
>
> Modified:
> httpd/httpd/branches/2.4.x/STATUS
>
[]
>   trunk patch: http://svn.apache.org/r1717816
>   +1: wrowe, icing
> + ylavic: how about adding !ap_request_has_body(r) to the test then?

E.g. (on top of r1717816):

Index: modules/ssl/ssl_engine_kernel.c
===
--- modules/ssl/ssl_engine_kernel.c(revision 1718341)
+++ modules/ssl/ssl_engine_kernel.c(working copy)
@@ -252,7 +252,7 @@ int ssl_hook_ReadReq(request_rec *r)
  * and OPTIONS * request processing is completed.
  */
 if (sc->enabled == SSL_ENABLED_OPTIONAL && !(sslconn && sslconn->ssl)
-&& !r->main) {
+&& ap_is_initial_req(r) && !ap_has_request_body(r)) {
 apr_table_setn(r->headers_out, "Upgrade", "TLS/1.0, HTTP/1.1");
 apr_table_mergen(r->headers_out, "Connection", "upgrade");
 }
--

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Yann Ylavic]

On Tue, Dec 8, 2015 at 2:37 PM, Yann Ylavic  wrote:
> On Tue, Dec 8, 2015 at 2:30 PM,   wrote:
>> Author: ylavic
>> Date: Tue Dec  8 13:30:30 2015
>> New Revision: 1718595
>>
>> URL: http://svn.apache.org/viewvc?rev=1718595=rev
>> Log:
>> Comment about ap_request_has_body() check for Upgrade.
>>
>> Modified:
>> httpd/httpd/branches/2.4.x/STATUS
>>
> []
>>   trunk patch: http://svn.apache.org/r1717816
>>   +1: wrowe, icing
>> + ylavic: how about adding !ap_request_has_body(r) to the test then?
>
> E.g. (on top of r1717816):

Actually, since there is already an Upgrade handling above, wouldn't a more
correct patch be (trunk):

Index: modules/ssl/ssl_engine_kernel.c
===
--- modules/ssl/ssl_engine_kernel.c(revision 1718341)
+++ modules/ssl/ssl_engine_kernel.c(working copy)
@@ -230,10 +230,13 @@ int ssl_hook_ReadReq(request_rec *r)

 /* Perform TLS upgrade here if "SSLEngine optional" is configured,
  * SSL is not already set up for this connection, and the client
- * has sent a suitable Upgrade header. */
+ * has sent a suitable Upgrade header. Note this must happen before
+ * map_to_storage and OPTIONS * request processing is completed.
+ */
 if (sc->enabled == SSL_ENABLED_OPTIONAL && !myConnConfig(r->connection)
 && (upgrade = apr_table_get(r->headers_in, "Upgrade")) != NULL
-&& ap_find_token(r->pool, upgrade, "TLS/1.0")) {
+&& ap_find_token(r->pool, upgrade, "TLS/1.0")
+&& !r->main && !ap_has_request_body(r)) {
 if (upgrade_connection(r)) {
 return AP_FILTER_ERROR;
 }
@@ -246,17 +249,6 @@ int ssl_hook_ReadReq(request_rec *r)
 sslconn = myConnConfig(r->connection->master);
 }

-/* If "SSLEngine optional" is configured, this is not an SSL
- * connection, and this isn't a subrequest, send an Upgrade
- * response header.  Note this must happen before map_to_storage
- * and OPTIONS * request processing is completed.
- */
-if (sc->enabled == SSL_ENABLED_OPTIONAL && !(sslconn && sslconn->ssl)
-&& !r->main) {
-apr_table_setn(r->headers_out, "Upgrade", "TLS/1.0, HTTP/1.1");
-apr_table_mergen(r->headers_out, "Connection", "upgrade");
-}
-
 if (!sslconn) {
 return DECLINED;
 }
?

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Jim Jagielski]

My only suggestion is that instead of willy-nilly suggesting
patches that will be included in a release, that we actually take
time to think of the correct patch, to implement it and TEST against
it and only THEN have it backported.

Please.

We don't want to put out a semi-immediate 2.4.19 because one
of these last-minute patches broke other stuff. It looks, and
is, really, really bad and amateur.

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[William A Rowe Jr]

On Tue, Dec 8, 2015 at 7:37 AM, Yann Ylavic  wrote:

> On Tue, Dec 8, 2015 at 2:30 PM,   wrote:
> > Author: ylavic
> > Date: Tue Dec  8 13:30:30 2015
> > New Revision: 1718595
> >
> > URL: http://svn.apache.org/viewvc?rev=1718595=rev
> > Log:
> > Comment about ap_request_has_body() check for Upgrade.
> >
> > Modified:
> > httpd/httpd/branches/2.4.x/STATUS
> >
> []
> >   trunk patch: http://svn.apache.org/r1717816
> >   +1: wrowe, icing
> > + ylavic: how about adding !ap_request_has_body(r) to the test then?
>
> E.g. (on top of r1717816):
>
> Index: modules/ssl/ssl_engine_kernel.c
> ===
> --- modules/ssl/ssl_engine_kernel.c(revision 1718341)
> +++ modules/ssl/ssl_engine_kernel.c(working copy)
> @@ -252,7 +252,7 @@ int ssl_hook_ReadReq(request_rec *r)
>   * and OPTIONS * request processing is completed.
>   */
>  if (sc->enabled == SSL_ENABLED_OPTIONAL && !(sslconn && sslconn->ssl)
> -&& !r->main) {
> +&& ap_is_initial_req(r) && !ap_has_request_body(r)) {
>  apr_table_setn(r->headers_out, "Upgrade", "TLS/1.0, HTTP/1.1");
>  apr_table_mergen(r->headers_out, "Connection", "upgrade");
>  }
>
>
The problem is that you are disabling *advertising* of the protocol based
on the content of a request body.  *This* request isn't going to be the
target
of the user's advertisement, that applies to their *next* request.  It
doesn't
change what I think you meant to change.

On the next request, your patch disables the advertising in an OPTIONS *
request because you didn't send the first advertisement; that won't work
out.
You are also disabling per-context advertisement which is allowed by
RFC7230.
E.g. content under /cups/devices/ may actually have an SSLRequireSSL.  Right
now the 426 code path relies on advertising headers already being present.

We save lots of response bytes on kept-alive SSLEngine optional resources
by advertising less frequently as you suggest above, but we can't have an
_initial_req toggle without later re-injecting these into all 426 exception
paths,
per the upgrade required exception's definition.

The core Protocols API already suffers this problem, e.g. WebSockets.  They
may apply to all resources within /webapp/ but not to other resources on the
server, and the current API won't present the upgrade header in response to
the specific resources desired.

Since we have the read-ahead buffering already, I don't see a reason to
simply
disable it at this time, the patch to switch the sequence of 101 and 100
should
be straightforward.  Since we aren't converging quite yet on an API fix to
solve
this multifaceted case, I'll look at the simple fix within mod_ssl alone.
Since
the logic was valid under RFC2718/2616 I don't think we have to do a hard
stop
to fix such a bug for RFC7230 here today, but can incorporate such fixes in
2.4.19 soon.

Cheers,

Bill

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[William A Rowe Jr]

On Tue, Dec 8, 2015 at 8:34 AM, Stefan Eissing <stefan.eiss...@greenbytes.de
> wrote:

> +1 for deferring any upgrade changes that do not fix real issues - like
> the one proposed for backport by Bill - to 2.4.19
>

Agreed, as spelled out in my top-post, simplest path to 2.4.18, and these
interesting discussions over the past day point to no single simple path.

Note that the pre-patch behavior caused tls to overwrite h2c, now the
protocol
API will overwrite tls upgrade advertisements on the first trip through.

Does it make sense to @bug the new Protocol API's stating that these
remain experimental and still subject to change, and refer prospective
developer/consumers to dev@httpd?  It seems something will change
in a later 2.4 release, and its simply a matter of what is the appropriate
straight path that can satisfy all of the prospective upgrade consumers.

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Stefan Eissing]

With the current implementation, that seems wise. This restriction can be 
removed once the change we discussed with output filter/hook is working.

> Am 08.12.2015 um 14:37 schrieb Yann Ylavic :
> 
> On Tue, Dec 8, 2015 at 2:30 PM,   wrote:
>> Author: ylavic
>> Date: Tue Dec  8 13:30:30 2015
>> New Revision: 1718595
>> 
>> URL: http://svn.apache.org/viewvc?rev=1718595=rev
>> Log:
>> Comment about ap_request_has_body() check for Upgrade.
>> 
>> Modified:
>>httpd/httpd/branches/2.4.x/STATUS
>> 
> []
>>  trunk patch: http://svn.apache.org/r1717816
>>  +1: wrowe, icing
>> + ylavic: how about adding !ap_request_has_body(r) to the test then?
> 
> E.g. (on top of r1717816):
> 
> Index: modules/ssl/ssl_engine_kernel.c
> ===
> --- modules/ssl/ssl_engine_kernel.c(revision 1718341)
> +++ modules/ssl/ssl_engine_kernel.c(working copy)
> @@ -252,7 +252,7 @@ int ssl_hook_ReadReq(request_rec *r)
>  * and OPTIONS * request processing is completed.
>  */
> if (sc->enabled == SSL_ENABLED_OPTIONAL && !(sslconn && sslconn->ssl)
> -&& !r->main) {
> +&& ap_is_initial_req(r) && !ap_has_request_body(r)) {
> apr_table_setn(r->headers_out, "Upgrade", "TLS/1.0, HTTP/1.1");
> apr_table_mergen(r->headers_out, "Connection", "upgrade");
> }
> --

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Stefan Eissing]

> Am 08.12.2015 um 16:18 schrieb William A Rowe Jr <wr...@rowe-clan.net>:
> 
> On Tue, Dec 8, 2015 at 8:34 AM, Stefan Eissing <stefan.eiss...@greenbytes.de> 
> wrote:
> +1 for deferring any upgrade changes that do not fix real issues - like the 
> one proposed for backport by Bill - to 2.4.19
> 
> Agreed, as spelled out in my top-post, simplest path to 2.4.18, and these
> interesting discussions over the past day point to no single simple path.
> 
> Note that the pre-patch behavior caused tls to overwrite h2c, now the protocol
> API will overwrite tls upgrade advertisements on the first trip through.
> 
> Does it make sense to @bug the new Protocol API's stating that these
> remain experimental and still subject to change, and refer prospective 
> developer/consumers to dev@httpd?  It seems something will change
> in a later 2.4 release, and its simply a matter of what is the appropriate
> straight path that can satisfy all of the prospective upgrade consumers.

+1

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Stefan Eissing]

+1 for deferring any upgrade changes that do not fix real issues - like the one 
proposed for backport by Bill - to 2.4.19

> Am 08.12.2015 um 15:29 schrieb William A Rowe Jr :
> 
> On Tue, Dec 8, 2015 at 7:37 AM, Yann Ylavic  wrote:
> On Tue, Dec 8, 2015 at 2:30 PM,   wrote:
> > Author: ylavic
> > Date: Tue Dec  8 13:30:30 2015
> > New Revision: 1718595
> >
> > URL: http://svn.apache.org/viewvc?rev=1718595=rev
> > Log:
> > Comment about ap_request_has_body() check for Upgrade.
> >
> > Modified:
> > httpd/httpd/branches/2.4.x/STATUS
> >
> []
> >   trunk patch: http://svn.apache.org/r1717816
> >   +1: wrowe, icing
> > + ylavic: how about adding !ap_request_has_body(r) to the test then?
> 
> E.g. (on top of r1717816):
> 
> Index: modules/ssl/ssl_engine_kernel.c
> ===
> --- modules/ssl/ssl_engine_kernel.c(revision 1718341)
> +++ modules/ssl/ssl_engine_kernel.c(working copy)
> @@ -252,7 +252,7 @@ int ssl_hook_ReadReq(request_rec *r)
>   * and OPTIONS * request processing is completed.
>   */
>  if (sc->enabled == SSL_ENABLED_OPTIONAL && !(sslconn && sslconn->ssl)
> -&& !r->main) {
> +&& ap_is_initial_req(r) && !ap_has_request_body(r)) {
>  apr_table_setn(r->headers_out, "Upgrade", "TLS/1.0, HTTP/1.1");
>  apr_table_mergen(r->headers_out, "Connection", "upgrade");
>  }
> 
> 
> The problem is that you are disabling *advertising* of the protocol based
> on the content of a request body.  *This* request isn't going to be the target
> of the user's advertisement, that applies to their *next* request.  It doesn't
> change what I think you meant to change.
> 
> On the next request, your patch disables the advertising in an OPTIONS *
> request because you didn't send the first advertisement; that won't work out.
> You are also disabling per-context advertisement which is allowed by RFC7230.
> E.g. content under /cups/devices/ may actually have an SSLRequireSSL.  Right
> now the 426 code path relies on advertising headers already being present.
> 
> We save lots of response bytes on kept-alive SSLEngine optional resources 
> by advertising less frequently as you suggest above, but we can't have an 
> _initial_req toggle without later re-injecting these into all 426 exception 
> paths,
> per the upgrade required exception's definition.
> 
> The core Protocols API already suffers this problem, e.g. WebSockets.  They
> may apply to all resources within /webapp/ but not to other resources on the
> server, and the current API won't present the upgrade header in response to
> the specific resources desired.
> 
> Since we have the read-ahead buffering already, I don't see a reason to simply
> disable it at this time, the patch to switch the sequence of 101 and 100 
> should
> be straightforward.  Since we aren't converging quite yet on an API fix to 
> solve
> this multifaceted case, I'll look at the simple fix within mod_ssl alone.  
> Since
> the logic was valid under RFC2718/2616 I don't think we have to do a hard stop
> to fix such a bug for RFC7230 here today, but can incorporate such fixes in
> 2.4.19 soon.
> 
> Cheers,
> 
> Bill

Re: Upgrade when !ap_request_has_body(r) only? (was: for 2.4.18)

[Yann Ylavic]

On Tue, Dec 8, 2015 at 3:29 PM, William A Rowe Jr  wrote:
> On Tue, Dec 8, 2015 at 7:37 AM, Yann Ylavic  wrote:
>>
>> E.g. (on top of r1717816):
>
> The problem is that you are disabling *advertising* of the protocol based
> on the content of a request body.  *This* request isn't going to be the
> target
> of the user's advertisement, that applies to their *next* request.  It
> doesn't
> change what I think you meant to change.

Yes, you are right, the real Upgrade is done above, so when we are
here we just prepare the response headers.
Let's think/agree more about how to handle Upgrades in the next release(s).

Regards,
Yann.

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Yann Ylavic]

On Tue, Dec 8, 2015 at 3:17 PM, Jim Jagielski <j...@jagunet.com> wrote:
> My only suggestion is that instead of willy-nilly suggesting
> patches that will be included in a release, that we actually take
> time to think of the correct patch, to implement it and TEST against
> it and only THEN have it backported.
>
> Please.

Suggestions have to start somewhere, I did not mean to rush on this,
just expecting feedbacks (including ones like yours, which is indeed
very sensible :)

My point was that if we were backport r1717816 in 2.4.18 (for OPTIONS
to work back), we needed more changes for RFC-compliance wrt TLS/1.x
Upgrades, the one w/o the other is not suitable.

So I think we all agree on the need to think/test more about this ;)

Re: Protocol API @bug warnings for 2.4.18?

[Stefan Eissing]

+1 Fine by me.

> Am 08.12.2015 um 16:31 schrieb William A Rowe Jr <wr...@rowe-clan.net>:
> 
> On Tue, Dec 8, 2015 at 9:21 AM, Stefan Eissing <stefan.eiss...@greenbytes.de> 
> wrote:
> 
> > On Tue, Dec 8, 2015 at 8:34 AM, Stefan Eissing 
> > <stefan.eiss...@greenbytes.de> wrote:
> > +1 for deferring any upgrade changes
> >
> > Agreed, as spelled out in my top-post, simplest path to 2.4.18, and these
> > interesting discussions over the past day point to no single simple path.
> >
> > Does it make sense to @bug the new Protocol API's stating that these
> > remain experimental and still subject to change, and refer prospective
> > developer/consumers to dev@httpd?  It seems something will change
> > in a later 2.4 release, and its simply a matter of what is the appropriate
> > straight path that can satisfy all of the prospective upgrade consumers.
> 
> +1
> 
> Something like the attached?  Edits/suggestions welcome.
> 
> 
> 
>  
> 
> 

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Jim Jagielski]

> On Dec 8, 2015, at 11:11 AM, Yann Ylavic <ylavic@gmail.com> wrote:
> 
> On Tue, Dec 8, 2015 at 3:17 PM, Jim Jagielski <j...@jagunet.com> wrote:
>> My only suggestion is that instead of willy-nilly suggesting
>> patches that will be included in a release, that we actually take
>> time to think of the correct patch, to implement it and TEST against
>> it and only THEN have it backported.
>> 
>> Please.
> 
> Suggestions have to start somewhere, I did not mean to rush on this,
> just expecting feedbacks (including ones like yours, which is indeed
> very sensible :)
> 
> My point was that if we were backport r1717816 in 2.4.18 (for OPTIONS
> to work back), we needed more changes for RFC-compliance wrt TLS/1.x
> Upgrades, the one w/o the other is not suitable.
> 
> So I think we all agree on the need to think/test more about this ;)

Oh, agreed 100%.

Protocol API @bug warnings for 2.4.18?

[William A Rowe Jr]

On Tue, Dec 8, 2015 at 9:21 AM, Stefan Eissing <stefan.eiss...@greenbytes.de
> wrote:

>
> > On Tue, Dec 8, 2015 at 8:34 AM, Stefan Eissing <
> stefan.eiss...@greenbytes.de> wrote:
> > +1 for deferring any upgrade changes
> >
> > Agreed, as spelled out in my top-post, simplest path to 2.4.18, and these
> > interesting discussions over the past day point to no single simple path.
> >
> > Does it make sense to @bug the new Protocol API's stating that these
> > remain experimental and still subject to change, and refer prospective
> > developer/consumers to dev@httpd?  It seems something will change
> > in a later 2.4 release, and its simply a matter of what is the
> appropriate
> > straight path that can satisfy all of the prospective upgrade consumers.
>
> +1
>

Something like the attached?  Edits/suggestions welcome.
Index: include/http_protocol.h
===
--- include/http_protocol.h	(revision 1718631)
+++ include/http_protocol.h	(working copy)
@@ -736,6 +736,10 @@
  *   NULL to indicated that the hooks are free to propose 
  * @param proposals The list of protocol identifiers proposed by the hooks
  * @return OK or DECLINED
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE_HOOK(int,protocol_propose,(conn_rec *c, request_rec *r,
   server_rec *s,
@@ -765,6 +769,10 @@
  * @param choices A list of protocol identifiers, normally the clients whishes
  * @param proposals the list of protocol identifiers proposed by the hooks
  * @return OK or DECLINED
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE_HOOK(int,protocol_switch,(conn_rec *c, request_rec *r,
  server_rec *s,
@@ -780,6 +788,10 @@
  *
  * @param c The current connection
  * @return The identifier of the protocol in place or NULL
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE_HOOK(const char *,protocol_get,(const conn_rec *c))
 
@@ -798,6 +810,10 @@
  * @param report_all include also protocols less preferred than the current one
  * @param pupgrades on return, possible protocols to upgrade to in descending order 
  * of preference. Maybe NULL if none are available.
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE(apr_status_t) ap_get_protocol_upgrades(conn_rec *c, request_rec *r, 
   server_rec *s, int report_all, 
@@ -817,6 +833,10 @@
  * @param s The server/virtual host selected
  * @param choices A list of protocol identifiers, normally the clients whishes
  * @return The selected protocol or NULL if no protocol could be agreed upon
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE(const char *) ap_select_protocol(conn_rec *c, request_rec *r, 
 server_rec *s,
@@ -835,6 +855,10 @@
  * APR_EINVAL,  if the protocol is already in place
  * APR_NOTIMPL, if no module performed the switch
  * Other errors where appropriate
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE(apr_status_t) ap_switch_protocol(conn_rec *c, request_rec *r, 
 server_rec *s,
@@ -850,6 +874,10 @@
  *
  * @param c The connection to determine the protocol for
  * @return the protocol in use, never NULL
+ * @bug This API or implementation and order of operations should be considered
+ * experimental and will continue to evolve in future 2.4 releases, with
+ * a corresponding minor module magic number (MMN) bump to indicate the
+ * API revision level.
  */
 AP_DECLARE(const c

Re: Upgrade when !ap_request_has_body(r) only for 2.4.18? (was: svn commit: r1718595 - /httpd/httpd/branches/2.4.x/STATUS)

[Jim Jagielski]

So what is current (r1718631) is likely what will be tagged and rolled
and, assuming enuff +1s, released.

Re: Protocol API @bug warnings for 2.4.18?

[Yann Ylavic]

On Tue, Dec 8, 2015 at 4:31 PM, William A Rowe Jr <wr...@rowe-clan.net> wrote:
> On Tue, Dec 8, 2015 at 9:21 AM, Stefan Eissing
> <stefan.eiss...@greenbytes.de> wrote:
>>
>>
>> > On Tue, Dec 8, 2015 at 8:34 AM, Stefan Eissing
>> > <stefan.eiss...@greenbytes.de> wrote:
>> > +1 for deferring any upgrade changes
>> >
>> > Agreed, as spelled out in my top-post, simplest path to 2.4.18, and
>> > these
>> > interesting discussions over the past day point to no single simple
>> > path.
>> >
>> > Does it make sense to @bug the new Protocol API's stating that these
>> > remain experimental and still subject to change, and refer prospective
>> > developer/consumers to dev@httpd?  It seems something will change
>> > in a later 2.4 release, and its simply a matter of what is the
>> > appropriate
>> > straight path that can satisfy all of the prospective upgrade consumers.
>>
>> +1
>
>
> Something like the attached?  Edits/suggestions welcome.

+1, we discussed this already for 2.4.17 but it did not make its way.
Thanks for doing it.

[VOTE] Release Apache httpd 2.4.18 as GA

[Jim Jagielski]

The pre-release test tarballs for Apache httpd 2.4.18 can be found
at the usual place:

http://httpd.apache.org/dev/dist/

I'm calling a VOTE on releasing these as Apache httpd 2.4.18 GA.

[ ] +1: Good to go
[ ] +0: meh
[ ] -1: Danger Will Robinson. And why.

Vote will last the normal 72 hrs.

NOTE: The *-deps are only there for convenience.

Thx!

2.4.18 T

[Stefan Eissing]

Everything as it should be from mod_http2 for this.

//Stefan

PS. Had one changed to the mod_http2.xml and when I 'make docs'ed it, I got too 
many changes locally. If someone with more knowledge than me on this would be 
so kind...

Re: NOTICE: Intent to T 2.4.18

[Jan Ehrhardt]

Jim Jagielski in gmane.comp.apache.devel (Sat, 5 Dec 2015 16:42:37 -0500):
>With the latest patches, I think we are in good shape.
>With that in mind, I plan to T on Tues (Dec 8)

I would not do that, unless
http://thread.gmane.org/gmane.comp.apache.devel/57728/focus=57827
is solved before Tuesday.
-- 
Jan

Re: NOTICE: Intent to T 2.4.18

[Stefan Eissing]

Excellent! I have one proposed backport regarding ssl vars and slave 
connections. If someone finds the time to look at it, that'd be great. It makes 
http2 work better with var checks for HTTPS in .htaccess files.

> Am 05.12.2015 um 22:42 schrieb Jim Jagielski :
> 
> With the latest patches, I think we are in good shape.
> With that in mind, I plan to T on Tues (Dec 8)

Re: NOTICE: Intent to T 2.4.18

[Jim Jagielski]

With the latest patches, I think we are in good shape.
With that in mind, I plan to T on Tues (Dec 8)

2.4.18 and mod_http2

[Stefan Eissing]

With the latest checkin into 2.4.x mod_http2 has everything I want for the 
2.4.18 release. Tests work for me here on OS X and Ubuntu, so I hope this will 
be fine.

Tomorrow I hopefully will find the time to make a blog about the upcoming 
changes in 2.4.18 re HTTP/2 and Apache httpd. Make some people looking forward 
to that release.

How would I open a http2 section in docs/manual similar to the ssl one? mkdir 
and index.xml? Link to that from where? 

Cheers,

  Stefan
 

Re: 2.4.18 and mod_http2

[William A Rowe Jr]

On Wed, Nov 25, 2015 at 11:35 AM, Stefan Eissing <
stefan.eiss...@greenbytes.de> wrote:

> With the latest checkin into 2.4.x mod_http2 has everything I want for the
> 2.4.18 release. Tests work for me here on OS X and Ubuntu, so I hope this
> will be fine.
>
> Tomorrow I hopefully will find the time to make a blog about the upcoming
> changes in 2.4.18 re HTTP/2 and Apache httpd. Make some people looking
> forward to that release.
>
> How would I open a http2 section in docs/manual similar to the ssl one?
> mkdir and index.xml?


Yup, that's the best kick-off.


> Link to that from where?
>

The mod_http2.xml page of course, but our docs crew can help thread the new
docs into the overall manual schema.  CC'ed.

Re: NOTICE: Intent to T 2.4.18

[Stefan Eissing]

Great! I try finish up the http2 stuff until Thursday as I will be unavailable 
next week. But everything looks good so far from my end. 

> Am 24.11.2015 um 20:09 schrieb Jim Jagielski <j...@jagunet.com>:
> 
> Just a head's up: I intend to T 2.4.18 around
> Nov 30th...

NOTICE: Intent to T 2.4.18

[Jim Jagielski]

Just a head's up: I intend to T 2.4.18 around
Nov 30th...

Re: 2.4.18?

[Daniel Gruno]

I don't care who the author is - if people keep up with toxic language
like what has been used in this thread, they will be removed from the
lists without any further warning.

Consider this your first, last and only warning. I trust I don't have to
go into details about who said what here.

With regards,
Daniel.

Re: 2.4.18?

[Noel Butler]

On 19/11/2015 01:43, Jim Jagielski wrote:

If you don't need the stuff in 2.4.18 and 2.4.17 is fine
for you then there is no need to upgrade...


I certainly wont be, nor will many others from what I've heard, anyway 
close to holidays now so wont be doing much anyway.




--
If you have the urge to reply to all rather than reply to list, you best
read  http://members.ausics.net/qwerty/

Re: 2.4.18?

[Noel Butler]

On 18/11/2015 19:48, Reindl Harald wrote:

Am 18.11.2015 um 08:16 schrieb Noel Butler:

On 17/11/2015 22:33, Reindl Harald wrote:


5 or 6 bloody weeks is a month - so what's the problem?
any other software but httpd is allowed to have monthly updates?

"I can accept" - seriously - you can just ignore a release when you
think it's not important for you but i don't get why anybody else
should wait for available non-security bugfixes just because you feel
like someone enforces you to update your server


your problem harry as usual is you dont comprehend whats said, because 
i

never once said it was OK for that other software, in fact its made
clear otherwise, but I'll grant you your comments based only on the 
fact

you have little comprehension of english and rely on translators.


no i don't rely on a translator, i just read you other posts too


oh  really this is not what you told us before, when you played hard dun 
by and getting kicked off lists and RBL'd - I probably still have the 
email, ahh thanks, so it confirms mew you are full of shit and your 
blacklisting  remains warranted :)





before reply and one part of that was "take phpmyadmin as one example,
most admins I know gave up updating it, because there were updates
every week, sometimes  every few days, Marc has accepted this is a
serious problem and unless a critical security bug is found, normal
bug fixes releases will be only once per month if need be"

and here we talk about that *one month* - so what's the problem?

anyways, if you can't cope with monthly updates and in doubt decide if
they are relevant at all hire somebody who can cope or just install a
LTS distribution only delivering critical bugfixes


i have better things to do with my time, like laugh at idiots like you


--
If you have the urge to reply to all rather than reply to list, you best
read  http://members.ausics.net/qwerty/

Re: 2.4.18?

[Graham Leggett]

On 18 Nov 2015, at 9:11 AM, Noel Butler  wrote:

> absolutely not! I personally only update  phpmyadmin once, on initial major 
> release, because I (like many others) were so of updating it every few days .

We’re catering for everybody here, not just your unique use case.

Regards,
Graham
—

Re: 2.4.18?

[Jim Jagielski]

If you don't need the stuff in 2.4.18 and 2.4.17 is fine
for you then there is no need to upgrade...

> On Nov 18, 2015, at 2:16 AM, Noel Butler <noel.but...@ausics.net> wrote:
> 
> On 17/11/2015 22:33, Reindl Harald wrote:
> 
>> 5 or 6 bloody weeks is a month - so what's the problem?
>> any other software but httpd is allowed to have monthly updates?
>> "I can accept" - seriously - you can just ignore a release when you
>> think it's not important for you but i don't get why anybody else
>> should wait for available non-security bugfixes just because you feel
>> like someone enforces you to update your server
> 
> your problem harry as usual is you dont comprehend whats said, because i 
> never once said it was OK for that other software, in fact its made clear 
> otherwise, but I'll grant you your comments based only on the fact you have 
> little comprehension of english and rely on translators.
> 
> 
> 
> -- 
> If you have the urge to reply to all rather than reply to list, you best
> read  http://members.ausics.net/qwerty/