blocking listener thread during SSL shutdown

[Frank Meier <fr...@ergon.ch>]

Hi

I've submitted a bug report [1] about hanging listener threads in 
mod_event during SSL shutdown. But since I did not hear anything I 
choose to discuss it on the Mailing List.

I was remotely debugging an Issue, where an Apache HTTPD did not serve 
requests any more. In the stacks of the HTTPD processes I saw that a lot 
of listener threads are blocked in a poll() call, triggered by 
modssl_smart_shutdown().

#0  0x00007f996d44f283 in poll () from /lib64/libc.so.6
#1  0x00007f996df8764f in apr_poll () from /opt/apache/bin/libapr-1.so.0
#2  0x00007f996eacb485 in ap_core_output_filter ()
#3  0x00007f996cf46488 in bio_filter_out_pass () from /opt/apache/bin/mod_ssl.so
#4  0x00007f996cf483bf in bio_filter_out_ctrl () from /opt/apache/bin/mod_ssl.so
#5  0x00007f996cf5803b in modssl_smart_shutdown () from /opt/apache/bin/mod_ssl.so
#6  0x00007f996cf4856e in ssl_filter_io_shutdown.isra.2 () from /opt/apache/bin/mod_ssl.so
#7  0x00007f996cf49c10 in ssl_io_filter_output () from /opt/apache/bin/mod_ssl.so
#8  0x00007f996cf46b4e in ssl_io_filter_coalesce () from /opt/apache/bin/mod_ssl.so
#9  0x00007f996ead9f93 in ap_shutdown_conn ()
#10 0x00007f996a505702 in start_lingering_close_nonblocking () from /opt/apache/bin/mod_mpm_event.so
#11 0x00007f996a5040ac in process_timeout_queue () from /opt/apache/bin/mod_mpm_event.so
#12 0x00007f996a5063b0 in listener_thread () from /opt/apache/bin/mod_mpm_event.so
#13 0x00007f996d90faa1 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f996d458aad in clone () from /lib64/libc.so.6

Unfortunately I'm not able to reproduce the problem locally. But just 
looking at this stack makes me think that this should never happen, 
since the listener thread is very important and should never block 
during a operation that is not waiting for new connections. Also the 
function name "start_lingering_close_nonblocking()" suggests, that this 
operation should not block, but obviously does.

I think it's quite serious, and can lead to problems where clients are 
not reacting "fast" to a SSL Shutdown alert. I also thought this 
behaviour could be exploited to be used as a DoS attack. But on the 
other hand it seems nobody else is experiencing this in the wild.

Am I misinterpreting something or does anyone else think this really is 
an issue?

cheers, Frank


[1] https://bz.apache.org/bugzilla/show_bug.cgi?id=60956

Re: blocking listener thread during SSL shutdown

[Frank Meier <fr...@ergon.ch>]

On 12/04/17 21:37, Eric Covener wrote:
> Any chance the logs also report write timeouts that precede this?  Are
> there "similar" threads waiting for writability of actual response
> data (e.g. ap_invoke_handler in the stack)
I'm not aware of any write timeouts in the httpd logs but then, this was 
a productive system with a "low" log level. Unfortunately I have no 
longer access to them.
I still have the stacks (printed with gstack) of all the HTTPD 
processes, there I see most of the worker threads are idle (waiting in 
ap_queue_pop_something ()), but some are indeed also blocked in a poll() 
triggered by apr_rflush() (flushing data to the client). But since they 
are worker threads this is just normal behaviour, I'd say.
The problem here is that the listener thread is blocked, which should 
never happen. I think if the listener thread is calling a function that 
might block, it should dispatch this task to another thread instead 
doing it itself. Or the function start_lingering_close_nonblocking() 
*really* has to be nonblocking.

Re: blocking listener thread during SSL shutdown

[Eric Covener <co...@gmail.com>]

On Wed, Apr 12, 2017 at 3:30 PM, Ruediger Pluem <rp...@apache.org> wrote:
> A debug build which states the line numbers would be more helpful here. What I can conclude so far by looking at the
> code is that it does not wait on the client to sent something but that it does wait on the socket to accept data for
> sending.
> So possibly the problem will go away if you fiddle around a little bit with the SendBufferSize.

Any chance the logs also report write timeouts that precede this?  Are
there "similar" threads waiting for writability of actual response
data (e.g. ap_invoke_handler in the stack)

Re: blocking listener thread during SSL shutdown

[Frank Meier <fr...@ergon.ch>]

On 12/04/17 21:30, Ruediger Pluem wrote:
> A debug build which states the line numbers would be more helpful here. What I can conclude so far by looking at the
> code is that it does not wait on the client to sent something but that it does wait on the socket to accept data for
> sending.
> So possibly the problem will go away if you fiddle around a little bit with the SendBufferSize.
Unfortunately I do no longer have access to the system, so we would have 
to stick to a theoretical approach :-(. Maybe an increase in 
SendBufferSize would mitigate the Issue, but in my opinion the code 
should be written that it could not block even the send buffer is full.
Or The listener thread should dispatch the closing to a worker thread, 
so it gets not distracted from handling new connections.

Frank Meier
Senior Software Engineer

-- 
frank.meier@ergon.ch, Phone: +41 44 268 87 35
Ergon Informatik AG, Merkurstrasse 43, CH-8032 Z�rich
http://www.ergon.ch

______________________________________________________________
e r g o n smart people - smart software

Re: blocking listener thread during SSL shutdown

[Ruediger Pluem <rp...@apache.org>]

On 04/12/2017 05:03 PM, Frank Meier wrote:
> Hi
> 
> I've submitted a bug report [1] about hanging listener threads in mod_event during SSL shutdown. But since I did not
> hear anything I choose to discuss it on the Mailing List.
> 
> I was remotely debugging an Issue, where an Apache HTTPD did not serve requests any more. In the stacks of the HTTPD
> processes I saw that a lot of listener threads are blocked in a poll() call, triggered by modssl_smart_shutdown().
> 
> #0  0x00007f996d44f283 in poll () from /lib64/libc.so.6
> #1  0x00007f996df8764f in apr_poll () from /opt/apache/bin/libapr-1.so.0
> #2  0x00007f996eacb485 in ap_core_output_filter ()
> #3  0x00007f996cf46488 in bio_filter_out_pass () from /opt/apache/bin/mod_ssl.so
> #4  0x00007f996cf483bf in bio_filter_out_ctrl () from /opt/apache/bin/mod_ssl.so
> #5  0x00007f996cf5803b in modssl_smart_shutdown () from /opt/apache/bin/mod_ssl.so
> #6  0x00007f996cf4856e in ssl_filter_io_shutdown.isra.2 () from /opt/apache/bin/mod_ssl.so
> #7  0x00007f996cf49c10 in ssl_io_filter_output () from /opt/apache/bin/mod_ssl.so
> #8  0x00007f996cf46b4e in ssl_io_filter_coalesce () from /opt/apache/bin/mod_ssl.so
> #9  0x00007f996ead9f93 in ap_shutdown_conn ()
> #10 0x00007f996a505702 in start_lingering_close_nonblocking () from /opt/apache/bin/mod_mpm_event.so
> #11 0x00007f996a5040ac in process_timeout_queue () from /opt/apache/bin/mod_mpm_event.so
> #12 0x00007f996a5063b0 in listener_thread () from /opt/apache/bin/mod_mpm_event.so
> #13 0x00007f996d90faa1 in start_thread () from /lib64/libpthread.so.0
> #14 0x00007f996d458aad in clone () from /lib64/libc.so.6

A debug build which states the line numbers would be more helpful here. What I can conclude so far by looking at the
code is that it does not wait on the client to sent something but that it does wait on the socket to accept data for
sending.
So possibly the problem will go away if you fiddle around a little bit with the SendBufferSize.

Regards

R�diger