You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Ruediger Pluem <rp...@apache.org> on 2015/09/30 20:30:59 UTC
Re: svn commit: r1705823 -
/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
On 09/29/2015 11:42 AM, ylavic@apache.org wrote:
> Author: ylavic
> Date: Tue Sep 29 09:42:56 2015
> New Revision: 1705823
>
> URL: http://svn.apache.org/viewvc?rev=1705823&view=rev
> Log:
> mod_ssl: don't FLUSH output (blocking) on read.
> This defeats deferred write (and pipelining), eg. check_pipeline() is not
> expecting the pipe to be flushed under it.
> So let OpenSSL >= 0.9.8m issue the flush when necessary (earlier versions
> are known to not handle all the cases, so we keep flushing with those).
>
> Modified:
> httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>
> Modified: httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
> URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c?rev=1705823&r1=1705822&r2=1705823&view=diff
> ==============================================================================
> --- httpd/httpd/trunk/modules/ssl/ssl_engine_io.c (original)
> +++ httpd/httpd/trunk/modules/ssl/ssl_engine_io.c Tue Sep 29 09:42:56 2015
> @@ -466,9 +466,10 @@ static int bio_filter_in_read(BIO *bio,
> }
>
> /* 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
> + * not to do so correctly in some cases (< 0.9.8m); see PR 46952.
> + */
> +#if OPENSSL_VERSION_NUMBER < 0x0009080df
> + /* 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
>
>
>
This and the follow up r1705826 do cause t/ssl/proxy.t to hang and ultimately fail with timeouts.
I am running on Centos 6 with Openssl 1.0.1.
Currently no idea why. Just a heads up.
Regards
Rüdiger
Re: svn commit: r1705823 - /httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
Posted by Jim Jagielski <ji...@jaguNET.com>.
I am still unclear on why this flushing is even necessary... :/
> On Sep 30, 2015, at 2:30 PM, Ruediger Pluem <rp...@apache.org> wrote:
>
>
>
> On 09/29/2015 11:42 AM, ylavic@apache.org wrote:
>> Author: ylavic
>> Date: Tue Sep 29 09:42:56 2015
>> New Revision: 1705823
>>
>> URL: http://svn.apache.org/viewvc?rev=1705823&view=rev
>> Log:
>> mod_ssl: don't FLUSH output (blocking) on read.
>> This defeats deferred write (and pipelining), eg. check_pipeline() is not
>> expecting the pipe to be flushed under it.
>> So let OpenSSL >= 0.9.8m issue the flush when necessary (earlier versions
>> are known to not handle all the cases, so we keep flushing with those).
>>
>> Modified:
>> httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>>
>> Modified: httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>> URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c?rev=1705823&r1=1705822&r2=1705823&view=diff
>> ==============================================================================
>> --- httpd/httpd/trunk/modules/ssl/ssl_engine_io.c (original)
>> +++ httpd/httpd/trunk/modules/ssl/ssl_engine_io.c Tue Sep 29 09:42:56 2015
>> @@ -466,9 +466,10 @@ static int bio_filter_in_read(BIO *bio,
>> }
>>
>> /* 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
>> + * not to do so correctly in some cases (< 0.9.8m); see PR 46952.
>> + */
>> +#if OPENSSL_VERSION_NUMBER < 0x0009080df
>> + /* 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
>>
>>
>>
>
>
> This and the follow up r1705826 do cause t/ssl/proxy.t to hang and ultimately fail with timeouts.
> I am running on Centos 6 with Openssl 1.0.1.
> Currently no idea why. Just a heads up.
>
> Regards
>
> Rüdiger
AW: svn commit: r1705823 -
/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
Posted by Plüm,
Rüdiger,
Vodafone Group <ru...@vodafone.com>.
> -----Ursprüngliche Nachricht-----
> Von: Yann Ylavic [mailto:ylavic.dev@gmail.com]
> Gesendet: Donnerstag, 1. Oktober 2015 16:47
> An: dev@httpd.apache.org
> Betreff: Re: svn commit: r1705823 -
> /httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>
> On Thu, Oct 1, 2015 at 3:54 PM, Plüm, Rüdiger, Vodafone Group
> <ru...@vodafone.com> wrote:
> >>
> >> Looks like as neither ssl23_client_hello nor ssl23_write_bytes cause
> >> BIO_flush to be called.
> >
> > Dumped the wrong memory section for a HEAP bucket. The contents of the
> heap bucket is actually (now a different session):
> >
> > gdb) x/70x 0x7f03a801c0e8
> > 0x7f03a801c0e8: 0x01010316 0x0100010c 0x56030308
> 0xcbee2e0d
> > 0x7f03a801c0f8: 0x08b833ba 0xfc96ae2b 0xba2b9a9b
> 0xa67ea8d2
> > 0x7f03a801c108: 0x0ef75ce9 0xb398fba7 0x004fe092
> 0x30c08a00
> > 0x7f03a801c118: 0x28c02cc0 0x14c024c0 0xa3000ac0
> 0x6b009f00
> > 0x7f03a801c128: 0x39006a00 0x88003800 0x32c08700
> 0x2ac02ec0
> > 0x7f03a801c138: 0x0fc026c0 0x9d0005c0 0x35003d00
> 0x2fc08400
> > 0x7f03a801c148: 0x27c02bc0 0x13c023c0 0xa20009c0
> 0x67009e00
> > 0x7f03a801c158: 0x33004000 0x12c03200 0x450008c0
> 0x16004400
> > 0x7f03a801c168: 0x31c01300 0x29c02dc0 0x0ec025c0
> 0x0dc004c0
> > 0x7f03a801c178: 0x9c0003c0 0x2f003c00 0x0a004100
> 0x99009a00
> > 0x7f03a801c188: 0x07009600 0x07c011c0 0x02c00cc0
> 0x04000500
> > 0x7f03a801c198: 0x12001500 0xff000900 0x55000001
> 0x0e000000
> > 0x7f03a801c1a8: 0x00000c00 0x636f6c09 0x6f686c61
> 0x0b007473
> > 0x7f03a801c1b8: 0x00030400 0x0a000201 0x06000800
> 0x18001900
> > 0x7f03a801c1c8: 0x23001700 0x0d000000 0x20002200
> 0x02060106
> > 0x7f03a801c1d8: 0x01050306 0x03050205 0x02040104
> 0x01030304
> > 0x7f03a801c1e8: 0x03030203 0x02020102 0x01010302
> 0x01000f00
> > 0x7f03a801c1f8: 0x00000001 0x00000000
> >
> > And this is indeed a client hello.
>
> Yes, I checked openssl's ssl23_client_hello() and indeed there is no
> flush from there...
>
> Actually I don't see any flush in any SSL_method*() during handshake
> but at the end of it...
>
> So we probably should go for something like:
>
> Index: modules/ssl/ssl_engine_io.c
> ===================================================================
> --- modules/ssl/ssl_engine_io.c (revision 1706228)
> +++ modules/ssl/ssl_engine_io.c (working copy)
> @@ -452,6 +452,7 @@ static int bio_filter_in_read(BIO *bio, char *in,
> apr_size_t inl = inlen;
> bio_filter_in_ctx_t *inctx = (bio_filter_in_ctx_t *)(bio->ptr);
> apr_read_type_e block = inctx->block;
> + int do_flush;
>
> inctx->rc = APR_SUCCESS;
>
> @@ -466,21 +467,25 @@ static int bio_filter_in_read(BIO *bio, char *in,
> }
>
> /* 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.
> + * not to do so correctly in some cases (< 0.9.8m; see PR 46952),
> + * or on the proxy/client side (after ssl23_client_hello(), eg.
> + * 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
> - /* 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) {
> + do_flush = 1;
> +#else
> + do_flush = !SSL_is_init_finished(inctx->ssl);
> +#endif
> + if (do_flush && bio_filter_out_flush(inctx->bio_out) < 0) {
> bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
> inctx->rc = outctx->rc;
> return -1;
> }
> -#endif
>
> BIO_clear_retry_flags(bio);
>
> --
>
> This makes the tests work for me...
Looks sensible. +1.
Regards
Rüdiger
Re: svn commit: r1705823 - /httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
Posted by Yann Ylavic <yl...@gmail.com>.
On Thu, Oct 1, 2015 at 3:54 PM, Plüm, Rüdiger, Vodafone Group
<ru...@vodafone.com> wrote:
>>
>> Looks like as neither ssl23_client_hello nor ssl23_write_bytes cause
>> BIO_flush to be called.
>
> Dumped the wrong memory section for a HEAP bucket. The contents of the heap bucket is actually (now a different session):
>
> gdb) x/70x 0x7f03a801c0e8
> 0x7f03a801c0e8: 0x01010316 0x0100010c 0x56030308 0xcbee2e0d
> 0x7f03a801c0f8: 0x08b833ba 0xfc96ae2b 0xba2b9a9b 0xa67ea8d2
> 0x7f03a801c108: 0x0ef75ce9 0xb398fba7 0x004fe092 0x30c08a00
> 0x7f03a801c118: 0x28c02cc0 0x14c024c0 0xa3000ac0 0x6b009f00
> 0x7f03a801c128: 0x39006a00 0x88003800 0x32c08700 0x2ac02ec0
> 0x7f03a801c138: 0x0fc026c0 0x9d0005c0 0x35003d00 0x2fc08400
> 0x7f03a801c148: 0x27c02bc0 0x13c023c0 0xa20009c0 0x67009e00
> 0x7f03a801c158: 0x33004000 0x12c03200 0x450008c0 0x16004400
> 0x7f03a801c168: 0x31c01300 0x29c02dc0 0x0ec025c0 0x0dc004c0
> 0x7f03a801c178: 0x9c0003c0 0x2f003c00 0x0a004100 0x99009a00
> 0x7f03a801c188: 0x07009600 0x07c011c0 0x02c00cc0 0x04000500
> 0x7f03a801c198: 0x12001500 0xff000900 0x55000001 0x0e000000
> 0x7f03a801c1a8: 0x00000c00 0x636f6c09 0x6f686c61 0x0b007473
> 0x7f03a801c1b8: 0x00030400 0x0a000201 0x06000800 0x18001900
> 0x7f03a801c1c8: 0x23001700 0x0d000000 0x20002200 0x02060106
> 0x7f03a801c1d8: 0x01050306 0x03050205 0x02040104 0x01030304
> 0x7f03a801c1e8: 0x03030203 0x02020102 0x01010302 0x01000f00
> 0x7f03a801c1f8: 0x00000001 0x00000000
>
> And this is indeed a client hello.
Yes, I checked openssl's ssl23_client_hello() and indeed there is no
flush from there...
Actually I don't see any flush in any SSL_method*() during handshake
but at the end of it...
So we probably should go for something like:
Index: modules/ssl/ssl_engine_io.c
===================================================================
--- modules/ssl/ssl_engine_io.c (revision 1706228)
+++ modules/ssl/ssl_engine_io.c (working copy)
@@ -452,6 +452,7 @@ static int bio_filter_in_read(BIO *bio, char *in,
apr_size_t inl = inlen;
bio_filter_in_ctx_t *inctx = (bio_filter_in_ctx_t *)(bio->ptr);
apr_read_type_e block = inctx->block;
+ int do_flush;
inctx->rc = APR_SUCCESS;
@@ -466,21 +467,25 @@ static int bio_filter_in_read(BIO *bio, char *in,
}
/* 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.
+ * not to do so correctly in some cases (< 0.9.8m; see PR 46952),
+ * or on the proxy/client side (after ssl23_client_hello(), eg.
+ * 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
- /* 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) {
+ do_flush = 1;
+#else
+ do_flush = !SSL_is_init_finished(inctx->ssl);
+#endif
+ if (do_flush && bio_filter_out_flush(inctx->bio_out) < 0) {
bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
inctx->rc = outctx->rc;
return -1;
}
-#endif
BIO_clear_retry_flags(bio);
--
This makes the tests work for me...
Regards,
Yann.
AW: svn commit: r1705823 -
/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
Posted by Plüm,
Rüdiger,
Vodafone Group <ru...@vodafone.com>.
> -----Ursprüngliche Nachricht-----
> Von: Ruediger Pluem [mailto:rpluem@apache.org]
> Gesendet: Mittwoch, 30. September 2015 22:02
> An: dev@httpd.apache.org
> Betreff: Re: svn commit: r1705823 -
> /httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>
> On 09/30/2015 08:30 PM, Ruediger Pluem wrote:
> >
> >
> > On 09/29/2015 11:42 AM, ylavic@apache.org wrote:
> >> Author: ylavic
> >> Date: Tue Sep 29 09:42:56 2015
> >> New Revision: 1705823
> >>
> >> URL: http://svn.apache.org/viewvc?rev=1705823&view=rev
> >> Log:
> >> mod_ssl: don't FLUSH output (blocking) on read.
> >> This defeats deferred write (and pipelining), eg. check_pipeline() is
> not
> >> expecting the pipe to be flushed under it.
> >> So let OpenSSL >= 0.9.8m issue the flush when necessary (earlier
> versions
> >> are known to not handle all the cases, so we keep flushing with
> those).
> >>
> >> Modified:
> >> httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
> >>
> >> Modified: httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
> >> URL:
> http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/ssl/ssl_engine_io
> .c?rev=1705823&r1=1705822&r2=1705823&view=diff
> >>
> ========================================================================
> ======
> >> --- httpd/httpd/trunk/modules/ssl/ssl_engine_io.c (original)
> >> +++ httpd/httpd/trunk/modules/ssl/ssl_engine_io.c Tue Sep 29 09:42:56
> 2015
> >> @@ -466,9 +466,10 @@ static int bio_filter_in_read(BIO *bio,
> >> }
> >>
> >> /* 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
> >> + * not to do so correctly in some cases (< 0.9.8m); see PR
> 46952.
> >> + */
> >> +#if OPENSSL_VERSION_NUMBER < 0x0009080df
> >> + /* 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
> >>
> >>
> >>
> >
> >
> > This and the follow up r1705826 do cause t/ssl/proxy.t to hang and
> ultimately fail with timeouts.
> > I am running on Centos 6 with Openssl 1.0.1.
> > Currently no idea why. Just a heads up.
> >
> > Regards
> >
> > Rüdiger
> >
>
>
> It is hanging here:
>
> 0x00007f1a810f0113 in __poll (fds=<value optimized out>, nfds=<value
> optimized out>, timeout=<value optimized out>) at
> ../sysdeps/unix/sysv/linux/poll.c:87
> #1 0x00007f1a81c6cdf7 in apr_wait_for_io_or_timeout (f=<value optimized
> out>, s=<value optimized out>, for_read=1) at
> support/unix/waitio.c:51
> #2 0x00007f1a81c66c3a in apr_socket_recv (sock=0x7f1a5400abb0,
> buf=0x7f1a5402a0e8 "", len=0x7f1a6e7814b0) at
> network_io/unix/sendrecv.c:87
> #3 0x00007f1a81c3f9e5 in socket_bucket_read (a=0x7f1a5400cbb8,
> str=0x7f1a6e7814b8, len=0x7f1a6e7814b0, block=<value
> optimized out>) at buckets/apr_buckets_socket.c:36
> #4 0x000000000044f30e in ap_core_input_filter (f=0x7f1a54013500,
> b=0x7f1a54013480, mode=<value optimized out>,
> block=APR_BLOCK_READ, readbytes=7) at core_filters.c:235
> #5 0x00007f1a79741f19 in logio_in_filter (f=<value optimized out>,
> bb=0x7f1a54013480, mode=<value optimized out>,
> block=<value optimized out>, readbytes=<value optimized out>) at
> mod_logio.c:165
> #6 0x00007f1a75e48339 in bio_filter_in_read (bio=0x7f1a540143f0,
> in=0x7f1a54019ce0 "", inlen=7) at ssl_engine_io.c:494
> #7 0x00007f1a758bf309 in BIO_read (b=0x7f1a540143f0,
> out=0x7f1a54019ce0, outl=7) at bio_lib.c:212
> #8 0x00007f1a75bf7873 in ssl23_read_bytes (s=0x7f1a54010a30, n=7) at
> s23_pkt.c:105
> #9 0x00007f1a75bf67be in ssl23_get_server_hello (s=0x7f1a54010a30) at
> s23_clnt.c:595
> #10 ssl23_connect (s=0x7f1a54010a30) at s23_clnt.c:226
> #11 0x00007f1a75e48b41 in ssl_io_filter_handshake
> (filter_ctx=0x7f1a5400f288) at ssl_engine_io.c:1162
> #12 0x00007f1a75e49a6b in ssl_io_filter_output (f=0x7f1a5400f2e0,
> bb=0x7f1a54008bf8) at ssl_engine_io.c:1702
> #13 0x00007f1a75e474c5 in ssl_io_filter_coalesce (f=0x7f1a5400f2b8,
> bb=0x7f1a54008bf8) at ssl_engine_io.c:1670
> #14 0x00007f1a77ece767 in ap_proxy_pass_brigade (bucket_alloc=<value
> optimized out>, r=0x7f1a54004980, p_conn=0x1ac1210,
> origin=0x7f1a5400ada0, bb=0x7f1a54008bf8, flush=<value optimized out>)
> at proxy_util.c:3640
> #15 0x00007f1a778a99ee in stream_reqbody_cl (r=0x7f1a54004980,
> worker=<value optimized out>, conf=0x1a3fd50,
> url=0x7f1a54006806 "https://localhost:8532/", proxyname=0x0,
> proxyport=35832) at mod_proxy_http.c:521
> #16 ap_proxy_http_request (r=0x7f1a54004980, worker=<value optimized
> out>, conf=0x1a3fd50, url=0x7f1a54006806
> "https://localhost:8532/", proxyname=0x0, proxyport=35832) at
> mod_proxy_http.c:1007
> #17 proxy_http_handler (r=0x7f1a54004980, worker=<value optimized out>,
> conf=0x1a3fd50, url=0x7f1a54006806
> "https://localhost:8532/", proxyname=0x0, proxyport=35832) at
> mod_proxy_http.c:2180
> #18 0x00007f1a77ec1002 in proxy_run_scheme_handler (r=0x7f1a54004980,
> worker=0x1a3ff58, conf=0x1a3fd50,
> url=0x7f1a54006806 "https://localhost:8532/", proxyhost=0x0,
> proxyport=0) at mod_proxy.c:2938
> #19 0x00007f1a77ec6793 in proxy_handler (r=0x7f1a54004980) at
> mod_proxy.c:1170
> #20 0x0000000000459f10 in ap_run_handler (r=0x7f1a54004980) at
> config.c:170
> #21 0x000000000045e0de in ap_invoke_handler (r=0x7f1a54004980) at
> config.c:433
> #22 0x00000000004722aa in ap_process_async_request (r=0x7f1a54004980) at
> http_request.c:338
> #23 0x000000000046e710 in ap_process_http_async_connection
> (c=0x7f1a68029578) at http_core.c:154
> #24 ap_process_http_connection (c=0x7f1a68029578) at http_core.c:248
> #25 0x0000000000464f80 in ap_run_process_connection (c=0x7f1a68029578)
> at connection.c:41
> #26 0x00007f1a73a30910 in process_socket (thd=0x18da030, dummy=<value
> optimized out>) at event.c:1137
> #27 worker_thread (thd=0x18da030, dummy=<value optimized out>) at
> event.c:2229
> #28 0x00007f1a81c6e298 in dummy_worker (opaque=0x18da030) at
> threadproc/unix/thread.c:145
> #29 0x00007f1a815d4a51 in start_thread (arg=0x7f1a6e782700) at
> pthread_create.c:301
> #30 0x00007f1a810f993d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
>
>
> And there is a HEAP bucket in the buffered_bb of the core output filter.
> I would guess that it is the Client Hello:
>
> dump of brigade 0x7f1a54013db8
> | type (address) | length | data addr | contents
> | rc
> ------------------------------------------------------------------------
> --------
> 0 | HEAP (0x7f1a5400ca78) | 273 | 0x7f1a5400cb18 |
> [~~~~~~~~~~~V~2~NO...] | 1
>
> Content is:
>
> x/70x 0x7f1a5400cb18
> 0x7f1a5400cb18: 0x00000001 0x00000000 0x540280d8
> 0x00007f1a
> 0x7f1a5400cb28: 0x00000111 0x00000000 0x0042b5a0
> 0x00000000
> 0x7f1a5400cb38: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb48: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb58: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb68: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb78: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb88: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cb98: 0x000000a0 0x00000000 0x5400ca38
> 0x00007f1a
> 0x7f1a5400cba8: 0x5400ca10 0x00007f1a 0x00000000
> 0x00000000
> 0x7f1a5400cbb8: 0x54013e10 0x00007f1a 0x54013e10
> 0x00007f1a
> 0x7f1a5400cbc8: 0x81e7eec0 0x00007f1a 0xffffffff
> 0xffffffff
> 0x7f1a5400cbd8: 0xffffffff 0xffffffff 0x5400abb0
> 0x00007f1a
> 0x7f1a5400cbe8: 0x0042b5a0 0x00000000 0x5400ca38
> 0x00007f1a
> 0x7f1a5400cbf8: 0x00016411 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cc08: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cc18: 0x00000000 0x00000000 0x00000000
> 0x00000000
> 0x7f1a5400cc28: 0x00000000 0x00000000
>
>
>
> Looks like as neither ssl23_client_hello nor ssl23_write_bytes cause
> BIO_flush to be called.
Dumped the wrong memory section for a HEAP bucket. The contents of the heap bucket is actually (now a different session):
gdb) x/70x 0x7f03a801c0e8
0x7f03a801c0e8: 0x01010316 0x0100010c 0x56030308 0xcbee2e0d
0x7f03a801c0f8: 0x08b833ba 0xfc96ae2b 0xba2b9a9b 0xa67ea8d2
0x7f03a801c108: 0x0ef75ce9 0xb398fba7 0x004fe092 0x30c08a00
0x7f03a801c118: 0x28c02cc0 0x14c024c0 0xa3000ac0 0x6b009f00
0x7f03a801c128: 0x39006a00 0x88003800 0x32c08700 0x2ac02ec0
0x7f03a801c138: 0x0fc026c0 0x9d0005c0 0x35003d00 0x2fc08400
0x7f03a801c148: 0x27c02bc0 0x13c023c0 0xa20009c0 0x67009e00
0x7f03a801c158: 0x33004000 0x12c03200 0x450008c0 0x16004400
0x7f03a801c168: 0x31c01300 0x29c02dc0 0x0ec025c0 0x0dc004c0
0x7f03a801c178: 0x9c0003c0 0x2f003c00 0x0a004100 0x99009a00
0x7f03a801c188: 0x07009600 0x07c011c0 0x02c00cc0 0x04000500
0x7f03a801c198: 0x12001500 0xff000900 0x55000001 0x0e000000
0x7f03a801c1a8: 0x00000c00 0x636f6c09 0x6f686c61 0x0b007473
0x7f03a801c1b8: 0x00030400 0x0a000201 0x06000800 0x18001900
0x7f03a801c1c8: 0x23001700 0x0d000000 0x20002200 0x02060106
0x7f03a801c1d8: 0x01050306 0x03050205 0x02040104 0x01030304
0x7f03a801c1e8: 0x03030203 0x02020102 0x01010302 0x01000f00
0x7f03a801c1f8: 0x00000001 0x00000000
And this is indeed a client hello.
Regards
Rüdiger
Re: svn commit: r1705823 -
/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
Posted by Ruediger Pluem <rp...@apache.org>.
On 09/30/2015 08:30 PM, Ruediger Pluem wrote:
>
>
> On 09/29/2015 11:42 AM, ylavic@apache.org wrote:
>> Author: ylavic
>> Date: Tue Sep 29 09:42:56 2015
>> New Revision: 1705823
>>
>> URL: http://svn.apache.org/viewvc?rev=1705823&view=rev
>> Log:
>> mod_ssl: don't FLUSH output (blocking) on read.
>> This defeats deferred write (and pipelining), eg. check_pipeline() is not
>> expecting the pipe to be flushed under it.
>> So let OpenSSL >= 0.9.8m issue the flush when necessary (earlier versions
>> are known to not handle all the cases, so we keep flushing with those).
>>
>> Modified:
>> httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>>
>> Modified: httpd/httpd/trunk/modules/ssl/ssl_engine_io.c
>> URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/ssl/ssl_engine_io.c?rev=1705823&r1=1705822&r2=1705823&view=diff
>> ==============================================================================
>> --- httpd/httpd/trunk/modules/ssl/ssl_engine_io.c (original)
>> +++ httpd/httpd/trunk/modules/ssl/ssl_engine_io.c Tue Sep 29 09:42:56 2015
>> @@ -466,9 +466,10 @@ static int bio_filter_in_read(BIO *bio,
>> }
>>
>> /* 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
>> + * not to do so correctly in some cases (< 0.9.8m); see PR 46952.
>> + */
>> +#if OPENSSL_VERSION_NUMBER < 0x0009080df
>> + /* 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
>>
>>
>>
>
>
> This and the follow up r1705826 do cause t/ssl/proxy.t to hang and ultimately fail with timeouts.
> I am running on Centos 6 with Openssl 1.0.1.
> Currently no idea why. Just a heads up.
>
> Regards
>
> Rüdiger
>
It is hanging here:
0x00007f1a810f0113 in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=<value optimized out>) at
../sysdeps/unix/sysv/linux/poll.c:87
#1 0x00007f1a81c6cdf7 in apr_wait_for_io_or_timeout (f=<value optimized out>, s=<value optimized out>, for_read=1) at
support/unix/waitio.c:51
#2 0x00007f1a81c66c3a in apr_socket_recv (sock=0x7f1a5400abb0, buf=0x7f1a5402a0e8 "", len=0x7f1a6e7814b0) at
network_io/unix/sendrecv.c:87
#3 0x00007f1a81c3f9e5 in socket_bucket_read (a=0x7f1a5400cbb8, str=0x7f1a6e7814b8, len=0x7f1a6e7814b0, block=<value
optimized out>) at buckets/apr_buckets_socket.c:36
#4 0x000000000044f30e in ap_core_input_filter (f=0x7f1a54013500, b=0x7f1a54013480, mode=<value optimized out>,
block=APR_BLOCK_READ, readbytes=7) at core_filters.c:235
#5 0x00007f1a79741f19 in logio_in_filter (f=<value optimized out>, bb=0x7f1a54013480, mode=<value optimized out>,
block=<value optimized out>, readbytes=<value optimized out>) at mod_logio.c:165
#6 0x00007f1a75e48339 in bio_filter_in_read (bio=0x7f1a540143f0, in=0x7f1a54019ce0 "", inlen=7) at ssl_engine_io.c:494
#7 0x00007f1a758bf309 in BIO_read (b=0x7f1a540143f0, out=0x7f1a54019ce0, outl=7) at bio_lib.c:212
#8 0x00007f1a75bf7873 in ssl23_read_bytes (s=0x7f1a54010a30, n=7) at s23_pkt.c:105
#9 0x00007f1a75bf67be in ssl23_get_server_hello (s=0x7f1a54010a30) at s23_clnt.c:595
#10 ssl23_connect (s=0x7f1a54010a30) at s23_clnt.c:226
#11 0x00007f1a75e48b41 in ssl_io_filter_handshake (filter_ctx=0x7f1a5400f288) at ssl_engine_io.c:1162
#12 0x00007f1a75e49a6b in ssl_io_filter_output (f=0x7f1a5400f2e0, bb=0x7f1a54008bf8) at ssl_engine_io.c:1702
#13 0x00007f1a75e474c5 in ssl_io_filter_coalesce (f=0x7f1a5400f2b8, bb=0x7f1a54008bf8) at ssl_engine_io.c:1670
#14 0x00007f1a77ece767 in ap_proxy_pass_brigade (bucket_alloc=<value optimized out>, r=0x7f1a54004980, p_conn=0x1ac1210,
origin=0x7f1a5400ada0, bb=0x7f1a54008bf8, flush=<value optimized out>)
at proxy_util.c:3640
#15 0x00007f1a778a99ee in stream_reqbody_cl (r=0x7f1a54004980, worker=<value optimized out>, conf=0x1a3fd50,
url=0x7f1a54006806 "https://localhost:8532/", proxyname=0x0, proxyport=35832) at mod_proxy_http.c:521
#16 ap_proxy_http_request (r=0x7f1a54004980, worker=<value optimized out>, conf=0x1a3fd50, url=0x7f1a54006806
"https://localhost:8532/", proxyname=0x0, proxyport=35832) at mod_proxy_http.c:1007
#17 proxy_http_handler (r=0x7f1a54004980, worker=<value optimized out>, conf=0x1a3fd50, url=0x7f1a54006806
"https://localhost:8532/", proxyname=0x0, proxyport=35832) at mod_proxy_http.c:2180
#18 0x00007f1a77ec1002 in proxy_run_scheme_handler (r=0x7f1a54004980, worker=0x1a3ff58, conf=0x1a3fd50,
url=0x7f1a54006806 "https://localhost:8532/", proxyhost=0x0, proxyport=0) at mod_proxy.c:2938
#19 0x00007f1a77ec6793 in proxy_handler (r=0x7f1a54004980) at mod_proxy.c:1170
#20 0x0000000000459f10 in ap_run_handler (r=0x7f1a54004980) at config.c:170
#21 0x000000000045e0de in ap_invoke_handler (r=0x7f1a54004980) at config.c:433
#22 0x00000000004722aa in ap_process_async_request (r=0x7f1a54004980) at http_request.c:338
#23 0x000000000046e710 in ap_process_http_async_connection (c=0x7f1a68029578) at http_core.c:154
#24 ap_process_http_connection (c=0x7f1a68029578) at http_core.c:248
#25 0x0000000000464f80 in ap_run_process_connection (c=0x7f1a68029578) at connection.c:41
#26 0x00007f1a73a30910 in process_socket (thd=0x18da030, dummy=<value optimized out>) at event.c:1137
#27 worker_thread (thd=0x18da030, dummy=<value optimized out>) at event.c:2229
#28 0x00007f1a81c6e298 in dummy_worker (opaque=0x18da030) at threadproc/unix/thread.c:145
#29 0x00007f1a815d4a51 in start_thread (arg=0x7f1a6e782700) at pthread_create.c:301
#30 0x00007f1a810f993d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
And there is a HEAP bucket in the buffered_bb of the core output filter. I would guess that it is the Client Hello:
dump of brigade 0x7f1a54013db8
| type (address) | length | data addr | contents | rc
--------------------------------------------------------------------------------
0 | HEAP (0x7f1a5400ca78) | 273 | 0x7f1a5400cb18 | [~~~~~~~~~~~V~2~NO...] | 1
Content is:
x/70x 0x7f1a5400cb18
0x7f1a5400cb18: 0x00000001 0x00000000 0x540280d8 0x00007f1a
0x7f1a5400cb28: 0x00000111 0x00000000 0x0042b5a0 0x00000000
0x7f1a5400cb38: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb48: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb58: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb68: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb78: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb88: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cb98: 0x000000a0 0x00000000 0x5400ca38 0x00007f1a
0x7f1a5400cba8: 0x5400ca10 0x00007f1a 0x00000000 0x00000000
0x7f1a5400cbb8: 0x54013e10 0x00007f1a 0x54013e10 0x00007f1a
0x7f1a5400cbc8: 0x81e7eec0 0x00007f1a 0xffffffff 0xffffffff
0x7f1a5400cbd8: 0xffffffff 0xffffffff 0x5400abb0 0x00007f1a
0x7f1a5400cbe8: 0x0042b5a0 0x00000000 0x5400ca38 0x00007f1a
0x7f1a5400cbf8: 0x00016411 0x00000000 0x00000000 0x00000000
0x7f1a5400cc08: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cc18: 0x00000000 0x00000000 0x00000000 0x00000000
0x7f1a5400cc28: 0x00000000 0x00000000
Looks like as neither ssl23_client_hello nor ssl23_write_bytes cause BIO_flush to be called.
Regards
Rüdiger