On 09/30/2015 08:30 PM, Ruediger Pluem wrote:
>
>
> On 09/29/2015 11:42 AM, [email protected] 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
