Created attachment 38585 [details]
check for h2eos bucket corruption

Hello,

starting with the big mod_http2 update in httpd-2.4.55 we see random
crashes in core_filter.c send_brigade_nonblocking/writev_nonblocking
because of corrupted buckets.

- the crashes do not occur when the current httpd-code (httpd-2.4.57)
  is used with mod_http2 from httpd-2.4.54.

- our servers are configured to run with 64 worker-threads per process,
  and the machines use redhat-linux. For each server which serves 
  about 20 million requests per day, we see between 1 and 5 crashes daily. 

- crashes occur always in the context of a HTTP2-request (mostly simple
  GET-requests). See example below.

- traces show that the crash happens always in cases where a h2eos
  bucket is destroyed and the following bucket from the brigade
  belongs to the same stream.

  see patch: httpd-trunk-mod_http2-check-for-h2eos-bucket-corruption
    
- the next/prev pointers of this following bucket sometimes point to
  illegal memory and indicate a use-after-free bug where the memory
  gets reused after the bucket-destroy-handler of the h2eos token
  was called.

- the patch checks for such cases in core_filter:send_brigade_nonblocking,
  and shows that the problem occurs far more often than the count of
  crashes we see.

- after a fresh apache restart it always takes some time (20-30 minutes)
  on our busy servers until the bug is triggered, so it might have todo
  with a special behavior of the apache-handlers in situtions where for
  example 'MaxConnectionsPerChild' is reached.

We are currently using a workaround to fix these crashes, which
was built to find out more about the problem:
 
- in h2_c1_io.c:pass_output the buckets are reordered, so that a 
  flush bucket and scratch heap bucket is inserted before the h2eos bucket
  when mod_http2 passes the output-brigade to the filters of other
  apache modules.
    
- since the h2eos<->flush swap fix in h2_c1_io.c seems not to be sufficient
  to catch all cases where a flush bucket is inserted, the remaining cases
  are swapped in core_filter.

  see patch: httpd-trunk-mod_http2-workaround-for-h2eos-bucket-corruption
  (should be applied on top of the other patch).

- with this patch applied the crashes are absent & the check doesn't trigger.

I think a real fix must more generally enforce the bucket-order in
mod_http2, so that h2eos is always the last bucket in a http2 stream.
Another possibility might be to allocate the flush/scratch-heap buckets
from a pool with a longer lifetime than the pool used for h2eos.

Example output when _checked_bucket_delete triggers:
---------------------------------------------------
[Tue Jun 06 12:49:55 2023] [error] [client ...] send_brigade_nonblocking_len0: BAD BUCKET type H2EOS bucket 0x7f681c0009c8 before:(next == 0x7f681c000d88, prev == 0x7f690c09df98) (next.next == 0x7f690c09df98, next.prev == 0x7f681c0009c8) (first == 0x7f681c0009c8, last == 0x7f681c000d88) bb-sentinel 0x7f690c09df98 after:next type FLUSH 0x7f681c000d88 (next == 0x7f681c000ba8, prev == 0x7f690c09df98) bb (first == 0x7f690c09df98, last == 0x7f690c09df98)

- before:
  head:  0x7f690c09df98 [first: h2eos, last: flush]
  h2eos: 0x7f681c0009c8 [next: flush, prev: head]
  flush: 0x7f681c000d88 [next: head, prev: h2eos]

- after bucket_delete(h2eos):
  head:  0x7f690c09df98 [first: head, last: head]
  flush: 0x7f681c000d88 [next: next, prev: head]
  next:  0x7f681c000ba8 ???

Example crash core:
------------------
Note: Line numbers here do not match repo because of included debug code.
      Such crashes occur after a check like above triggered in a 
      preceeding send_brigade_nonblocking loop iteration.

(gdb) bt
  #0  0x00007f1494013c68 in ?? ()
  #1  0x00000000004c9db7 in writev_nonblocking (s=s@entry=0x7f15d80b8340, bb=bb@entry=0x7f15d80b8af0, bytes_to_write=bytes_to_write@entry=361, nvec=nvec@entry=4, c=c@entry=0x7f15d80b8558, ctx=<optimized out>, ctx=<optimized out>) at core_filters.c:850 --> if (n) { apr_bucket_split() ... }
  #2  0x00000000004caf75 in send_brigade_nonblocking (c=0x7f15d80b8558, ctx=0x7f1494071678, bb=0x7f15d80b8af0, s=0x7f15d80b8340) at core_filters.c:819 --> if (nvec > 0) { rv = writev_nonblocking .. }
  #3  ap_core_output_filter (f=0x7f1494071348, new_bb=0x7f15d80b8af0) at core_filters.c:538
  #4  0x00000000005b58bc in ssl_io_filter_output (f=0x7f15d80b8aa8, bb=0x7f14940717e0) at ssl_engine_io.c:2094
  #5  0x00000000005b234e in ssl_io_filter_coalesce (f=0x7f15d80b8a80, bb=0x7f14940717e0) at ssl_engine_io.c:2037
  #6  0x00000000005ef937 in pass_output (flush=1, io=0x7f1494049af0) at h2_c1_io.c:281
  #7  h2_c1_io_assure_flushed (io=io@entry=0x7f1494049af0) at h2_c1_io.c:340
  #8  0x00000000005dc9f0 in h2_session_shutdown_notice (session=0x7f1494049ab0) at h2_session.c:735
  #9  h2_session_ev_mpm_stopping (arg=0, msg=0x0, session=0x7f1494049ab0) at h2_session.c:1524
  #10 h2_session_dispatch_event (session=0x7f1494049ab0, ev=<optimized out>, arg=0, msg=0x0) at h2_session.c:1726
  #11 0x00000000005de673 in h2_session_process (session=0x7f1494049ab0, async=0) at h2_session.c:1798
  #12 0x00000000005cb0a9 in h2_c1_run (c=c@entry=0x7f15d80b8558) at h2_c1.c:130
  #13 0x00000000005cb4bd in h2_c1_hook_process_connection (c=0x7f15d80b8558) at h2_c1.c:278
  #14 0x00000000004dbd10 in ap_run_process_connection (c=c@entry=0x7f15d80b8558) at connection.c:42
  #15 0x00000000004dc23e in ap_process_connection (c=c@entry=0x7f15d80b8558, csd=csd@entry=0x7f15d80b8340) at connection.c:217
  #16 0x00000000008212db in process_socket (bucket_alloc=0x7f1494013108, my_thread_num=8, my_child_num=102, sock=0x7f15d80b8340, p=0x7f15d80b82b8, thd=0x2e74528) at worker.c:485
  #17 worker_thread (thd=0x2e74528, dummy=<optimized out>) at worker.c:814
  #18 0x00007f15ff802ea5 in start_thread () from /lib64/libpthread.so.0
  #19 0x00007f15ff327b0d in clone () from /lib64/libc.so.6
(gdb) frame 1
(gdb) info locals
  apr__d = 0x7f15d80b8af8
  apr__b = 0x7f15d80b8af8
  bucket = 0x7f15d80b8af8
  n = 46
  rv = 0
  vec = <optimized out>
  bytes_written = 361
  i = 3
  offset = 3
(gdb) p *bb
  $1 = {p = 0x7f15d80b82b8, list = {next = 0x7f15d80b8af8, prev = 0x7f15d80b8af8}, bucket_alloc = 0x7f1494013108}
(gdb) p *bucket
  $2 = {link = {next = 0x7f15d80b8af8, prev = 0x7f15d80b8af8}, type = 0x7f1494013108, length = 139731795674416, start = 139731795675888, data = 0x92e640 <brigade_cleanup>, free = 0x987aa0 <apr_pool_cleanup_null>, list = 0x7f15d80b8b28}

Greetings,
Barnim