A note about mod_shib2 and mod_http2

[Jacob Lundberg]

Hi all,

We have been experimenting with HTTP/2 this month and although we don't
have the time to continue working on it this year I wanted to pass along
a note about interaction between mod_shib2 and mod_http2 in case it
might help (or warn) anybody on this list.

The Apache httpd folks stated HTTP/2 is stable now in 2.4.27 but there
is a locking patch which needs to be applied (bringing mod_http2 to
version 1.10.10).  However, even after that, we have been experiencing
stuck processes and occasional long pauses, possibly related to using
the httpd's graceful restart feature (I'm not sure if this is a
necessary precondition or not).

The stuck httpd threads appear to be stuck in mod_http2 code called by
mod_shib2 code.  F.e.:

Thread 193 (Thread 0x7fd082683700 (LWP 5966)):
#0  0x00007fd0f287f450 in __pthread_rwlock_wrlock_slow () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007fd0eca1271f in xmltooling::ReloadableXMLFile::lock() () from /usr/lib/x86_64-linux-gnu/libxmltooling-lite.so.7
#2  0x00007fd0ed49ceb3 in shibsp::AbstractSPRequest::AbstractSPRequest(char const*) () from /usr/lib/x86_64-linux-gnu/libshibsp-lite.so.7
#3  0x00007fd0ed7895e4 in ?? () from /usr/lib/apache2/modules/mod_shib2.so
#4  0x000055a0be6f80c0 in ap_run_post_read_request (r=r at entry=0x7fd0801870a0) at protocol.c:2344
#5  0x00007fd0e4685a8f in h2_request_create_rec (req=req at entry=0x7fd0801b7168, c=c at entry=0x7fd0801af0a0) at h2_request.c:314
#6  0x00007fd0e4691b44 in h2_task_process_request (c=0x7fd0801af0a0, task=<optimized out>) at h2_task.c:662
#7  h2_task_process_conn (c=0x7fd0801af0a0) at h2_task.c:728
#8  0x000055a0be718730 in ap_run_process_connection (c=c at entry=0x7fd0801af0a0) at connection.c:42
#9  0x00007fd0e4693327 in h2_task_do (task=0x7fd0801910a0, thread=thread at entry=0x7fd0f18e6230, worker_id=<optimized out>) at h2_task.c:638
#10 0x00007fd0e4696ef3 in slot_run (thread=0x7fd0f18e6230, wctx=0x7fd0f19c0028) at h2_workers.c:228
#11 0x00007fd0f287a494 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#12 0x00007fd0f25bbaff in clone () from /lib/x86_64-linux-gnu/libc.so.6

Here's a count of unique stack paths from one analysis run:

77: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>h2_request_create_rec>h2_task_process_request>h>ap_run_process_connection>h2_task_do>slot_run>start_thread>clone
1: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request
1: pthread_cond_wait@@GLIBC_2.3.2>get_next
1: pthread_cond_timedwait@@GLIBC_2.3.2>xmltooling::CondWaitImpl::timedwait(xmltooling::Mutex*,>??>start_thread>clone
1: __pthread_rwlock_wrlock_slow>??>xmltooling::ReloadableXMLFile::reload_fn(void*)>start_thread>clone
2: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>h2_request_create_rec>h2_task_process_request>h>ap_run_process_connection>h2_task_do
1: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>ap_read_request
58: pthread_cond_wait@@GLIBC_2.3.2>ap_queue_pop_something>worker_thread>start_thread>clone
1: pthread_cond_timedwait@@GLIBC_2.3.2>apr_thread_cond_timedwait>h2_mplx_release_and_join>session_cleanup>h2_session_pre_close>h2_conn_pre_close>ap_run_pre_close_connection>ap_prep_lingering_close>start_lingering_close_nonblocking>process_timeout_queue>listener_thread>start_thread>clone
49: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>ap_read_request>ap_process_http_async_connection>ap>ap_run_process_connection>process_socket>worker>start_thread>clone
1: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>ap_read_request>ap_process_http_async_connection>ap>ap_run_process_connection
2: __pthread_rwlock_wrlock_slow>xmltooling::ReloadableXMLFile::lock()>shibsp::AbstractSPRequest::AbstractSPRequest(char>??>ap_run_post_read_request>h2_request_create_rec>h2_task_process_request>h>ap_run_process_connection
108: pthread_cond_wait@@GLIBC_2.3.2>get_next>slot>start_thread>clone
19: pthread_cond_timedwait@@GLIBC_2.3.2>apr_thread_cond_timedwait>h2_mplx_release_and_join>session_cleanup>h2_session_pre_close>h2_conn_pre_close>ap_run_pre_close_connection>ap_prep_lingering_close>ap_start_lingering_close>start_lingering_close_blocking>process>worker>start_thread>clone

Disabling HTTP/2 restores normal behavior.  I'm not certain whether it
will be mod_shib2 or mod_http2 that needs to be adjusted to resolve the
issue.  We are using SP version 2.6.0.  At this point we have decided to
consider Apache httpd's HTTP/2 support immature and will not be using it
this year.

Thanks,
-Jacob

-- 

Jacob Lundberg
AVP, IT Architecture
503.290.0100 (voice)
503.973.5252 (fax)