Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

Bug#1036213: apache2: frequent SIGSEGV in mod_http2.so (purge_consumed_buckets)

150 views
Skip to first unread message

Bastien Durel

unread,
May 17, 2023, 6:40:05 AM5/17/23
to
Package: apache2
Version: 2.4.56-1~deb11u2
Severity: important

Dear Maintainer,

I see many segmentation faults in apache2, for exemple in the last 24h I got:

Tue 2023-05-16 13:40:59 CEST 775740 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 13:52:44 CEST 798329 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 16:15:46 CEST 810709 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 16:28:55 CEST 817483 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 17:59:23 CEST 823129 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 18:35:50 CEST 826974 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 18:44:15 CEST 831974 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 18:44:56 CEST 836174 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 18:54:56 CEST 822618 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 21:12:28 CEST 836246 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 21:21:10 CEST 853959 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 22:04:42 CEST 858749 33 33 11 present /usr/sbin/apache2
Tue 2023-05-16 23:26:09 CEST 866610 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 00:08:42 CEST 865968 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 00:24:04 CEST 874807 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 00:47:25 CEST 878675 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 01:42:14 CEST 877580 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 09:21:02 CEST 949781 33 33 11 present /usr/sbin/apache2
Wed 2023-05-17 09:50:49 CEST 954784 33 33 11 present /usr/sbin/apache2

All crashes I looked into are at the same function: purge_consumed_buckets at h2_bucket_beam.c:159

Here is the output of the "bt full" command from the core:

#0 0x00007ffb03778981 in purge_consumed_buckets (beam=beam@entry=0x7ffae452c0a0) at h2_bucket_beam.c:159
b = 0x7ffae45ea108
#1 0x00007ffb03778aaf in beam_shutdown (how=APR_SHUTDOWN_READWRITE, beam=<optimized out>) at h2_bucket_beam.c:258
No locals.
#2 beam_shutdown (how=APR_SHUTDOWN_READWRITE, beam=0x7ffae452c0a0) at h2_bucket_beam.c:242
No locals.
#3 beam_cleanup (data=0x7ffae452c0a0) at h2_bucket_beam.c:265
beam = 0x7ffae452c0a0
#4 0x00007ffb03e6780e in run_cleanups (cref=0x7ffae452c098) at ./memory/unix/apr_pools.c:2629
c = <optimized out>
c = <optimized out>
#5 apr_pool_destroy (pool=0x7ffae452c028) at ./memory/unix/apr_pools.c:987
active = <optimized out>
allocator = <optimized out>
#6 0x00007ffb03e6782d in apr_pool_destroy (pool=0x7ffae4530028) at ./memory/unix/apr_pools.c:997
active = <optimized out>
allocator = <optimized out>
#7 0x00007ffb03e6782d in apr_pool_destroy (pool=0x7ffae4551028) at ./memory/unix/apr_pools.c:997
active = <optimized out>
allocator = <optimized out>
#8 0x00007ffb03e6782d in apr_pool_destroy (pool=0x7ffae45a1028) at ./memory/unix/apr_pools.c:997
active = <optimized out>
allocator = <optimized out>
#9 0x00007ffb03e6782d in apr_pool_destroy (pool=0x7ffae4606028) at ./memory/unix/apr_pools.c:997
active = <optimized out>
allocator = <optimized out>
#10 0x00007ffb037914c5 in h2_session_pre_close (session=0x7ffae46060a0, async=<optimized out>) at h2_session.c:1988
status = 0
#11 0x00007ffb0377b745 in h2_c1_pre_close (ctx=<optimized out>, c=<optimized out>) at h2_c1.c:180
status = <optimized out>
conn_ctx = <optimized out>
#12 0x000056438478c9b0 in ap_run_pre_close_connection (c=c@entry=0x7ffae4614360) at connection.c:44
pHook = <optimized out>
n = 0
rv = 0
#13 0x000056438478cade in ap_prep_lingering_close (c=0x7ffae4614360) at connection.c:101
No locals.
#14 ap_start_lingering_close (c=0x7ffae4614360) at connection.c:127
csd = 0x7ffae46140b0
#15 0x00007ffb03b08abe in process_lingering_close (cs=0x7ffae46142b0) at event.c:1500
csd = 0x7ffae46140b0
dummybuf = "\027\003\003\000\023\067\020\251\027\003\215Re\345\310{\f8\312X\332N\310\375", '\000' <repeats 17385 times>...
nbytes = 0
rv = <optimized out>
q = <optimized out>
#16 0x00007ffb03b0a512 in process_socket (thd=thd@entry=0x7ffb037345c8, p=<optimized out>, sock=<optimized out>, cs=<optimized out>, my_child_num=my_child_num@entry=3, my_thread_num=my_thread_num@entry=16) at event.c:1238
c = <optimized out>
conn_id = <optimized out>
clogging = <optimized out>
rv = <optimized out>
rc = <optimized out>
#17 0x00007ffb03b0b125 in worker_thread (thd=0x7ffb037345c8, dummy=<optimized out>) at event.c:2199
csd = 0x7ffae46140b0
cs = 0x7ffae46142b0
te = 0x0
ptrans = 0x0
ti = <optimized out>
process_slot = -855667096
thread_slot = 16
rv = <optimized out>
is_idle = 0
#18 0x00007ffb03e2aea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
ret = <optimized out>
pd = <optimized out>
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140715157853952, -1517716079030320448, 140715846122926, 140715846122927, 140715157852032, 8396800, 1520638580441989824, 1520521782042673856}, mask_was_saved = 0}}, priv = {pad = {0x0,
0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
not_first_call = 0
#19 0x00007ffb03d4aa2f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

It may - or not - be related with the fact I got hundreds (had been hundreds of thousands) of persistent connections from random IR hosts to my https server, I guess it can put more stress on h2 cleanup functions that the normal (quite low) usage I had before.

I also seen that this function was corrected a few days ago : https://github.com/icing/mod_h2/commit/ff00b3fdff368b225e70c61ca0fefdbd3d83f6de
I don't know enough of apache2's codebase to see if it may has an impact, but it seems unlikely to me; as the AP_BUCKET_IS_EOR() check seems related to a newly introduced member

Regards,

-- Package-specific info:

-- System Information:
Debian Release: 11.7
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable-security'), (500, 'stable-debug'), (500, 'oldstable-updates'), (500, 'oldstable-debug'), (500, 'stable'), (500, 'oldstable')
Architecture: amd64 (x86_64)

Kernel: Linux 5.10.0-23-amd64 (SMP w/8 CPU threads)
Locale: LANG=fr_FR.UTF-8, LC_CTYPE=fr_FR.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages apache2 depends on:
ii apache2-bin 2.4.56-1~deb11u2
ii apache2-data 2.4.56-1~deb11u2
ii apache2-utils 2.4.56-1~deb11u2
ii dpkg 1.20.12
ii init-system-helpers 1.60
ii lsb-base 11.1.0
ii mime-support 3.66
ii perl 5.32.1-4+deb11u2
ii procps 2:3.3.17-5

Versions of packages apache2 recommends:
ii ssl-cert 1.1.0+nmu1

Versions of packages apache2 suggests:
pn apache2-doc <none>
ii apache2-suexec-pristine 2.4.56-1~deb11u2
ii chimera2 [www-browser] 2.0a19-8+b2
ii dillo [www-browser] 3.0.5-7
ii links2 [www-browser] 2.21-1+b1
ii lynx [www-browser] 2.9.0dev.6-3~deb11u1

Versions of packages apache2-bin depends on:
ii libapr1 1.7.0-6+deb11u2
ii libaprutil1 1.6.1-5+deb11u1
ii libaprutil1-dbd-sqlite3 1.6.1-5+deb11u1
ii libaprutil1-ldap 1.6.1-5+deb11u1
ii libbrotli1 1.0.9-2+b2
ii libc6 2.31-13+deb11u6
ii libcrypt1 1:4.4.18-4
ii libcurl4 7.74.0-1.3+deb11u7
ii libjansson4 2.13.1-1.1
ii libldap-2.4-2 2.4.57+dfsg-3+deb11u1
ii liblua5.3-0 5.3.3-1.1+b1
ii libnghttp2-14 1.43.0-1
ii libpcre3 2:8.44-2+0~20210301.9+debian11~1.gbpa278ad
ii libssl1.1 1.1.1n-0+deb11u4
ii libxml2 2.9.14+dfsg-0.1+0~20230421.14+debian11~1.gbpf14485
ii perl 5.32.1-4+deb11u2
ii zlib1g 1:1.2.11.dfsg-2+deb11u2

Versions of packages apache2-bin suggests:
pn apache2-doc <none>
ii apache2-suexec-pristine 2.4.56-1~deb11u2
ii chimera2 [www-browser] 2.0a19-8+b2
ii dillo [www-browser] 3.0.5-7
ii links2 [www-browser] 2.21-1+b1
ii lynx [www-browser] 2.9.0dev.6-3~deb11u1

Versions of packages apache2 is related to:
ii apache2 2.4.56-1~deb11u2
ii apache2-bin 2.4.56-1~deb11u2

-- Configuration Files:
/etc/apache2/apache2.conf changed [not included]
/etc/apache2/conf-available/security.conf changed [not included]
/etc/apache2/envvars changed [not included]
/etc/apache2/mods-available/cern_meta.load [Errno 2] Aucun fichier ou dossier de ce type: '/etc/apache2/mods-available/cern_meta.load'
/etc/apache2/mods-available/ident.load [Errno 2] Aucun fichier ou dossier de ce type: '/etc/apache2/mods-available/ident.load'
/etc/apache2/mods-available/imagemap.load [Errno 2] Aucun fichier ou dossier de ce type: '/etc/apache2/mods-available/imagemap.load'
/etc/apache2/mods-available/proxy_hcheck.load [Errno 2] Aucun fichier ou dossier de ce type: '/etc/apache2/mods-available/proxy_hcheck.load'
/etc/apache2/mods-available/proxy_html.load changed [not included]
/etc/apache2/mods-available/proxy_http2.load changed [not included]
/etc/apache2/mods-available/userdir.conf changed [not included]
/etc/apache2/ports.conf changed [not included]
/etc/apache2/sites-available/000-default.conf changed [not included]
/etc/apache2/sites-available/default-ssl.conf changed [not included]
/etc/cron.daily/apache2 changed [not included]
/etc/default/apache-htcacheclean [Errno 2] Aucun fichier ou dossier de ce type: '/etc/default/apache-htcacheclean'
/etc/init.d/apache2 changed [not included]
/etc/logrotate.d/apache2 changed [not included]

-- no debconf information

Stefan Eissing

unread,
May 17, 2023, 7:40:05 AM5/17/23
to
Sorry to hear about this. I think the recent change that could be relevant here is
the addition of:

h2_mplx.c#515: c1_purge_streams(m);

as seen in Apache httpd trunk and at https://github.com/icing/mod_h2.

This is intended to assure that streams and their requests are destroyed
in the right order when the connection is shut down.

Connection shutdown can happen at any time during request processing and
this makes it hard to reproduce issues in test cases. We have load tests
with well-behaving clients. Tests with mis-behaving ones are the tricky part.

It would be helpful if you could try https://github.com/icing/mod_h2/releases/tag/v2.0.15
on your system, to see how that is faring.

Kind Regards,
Stefan

Bastien Durel

unread,
May 18, 2023, 5:20:05 AM5/18/23
to
Hello,

I ran with /usr/lib/apache2/modules/mod_http2_2.0.15.so &
/usr/lib/apache2/modules/mod_proxy_http2_2.0.15.so since yesterday
15:20, and got a SIGSEGV at 21:29:30 : it's not in
purge_consumed_buckets but it's in the h2_proxy stack ...

Here is the bt full of the core:

#0 0x00007f9bb0464efe in ssl_io_filter_output (f=0x7f9ba02088d8, bb=0x7f9ba04cf3b8) at ssl_engine_io.c:1963
bucket = 0x7f9ba04c4108
status = 0
filter_ctx = 0x7f9ba0208880
inctx = <optimized out>
outctx = 0x7f9ba0208900
rblock = <optimized out>
#1 0x00007f9bb0597999 in proxy_pass_brigade (flush=1, bb=<optimized out>, origin=<optimized out>, p_conn=0x7f9ba020a0a0, bucket_alloc=<optimized out>) at h2_proxy_session.c:218
status = <optimized out>
transferred = 9
status = <optimized out>
transferred = <optimized out>
e = <optimized out>
ap__b = <optimized out>
#2 raw_send (ngh2=<optimized out>, data=<optimized out>, length=9, flags=<optimized out>, user_data=0x7f9ba04cf190) at h2_proxy_session.c:244
session = 0x7f9ba04cf190
b = <optimized out>
status = <optimized out>
flush = 1
#3 0x00007f9bb14a11f9 in nghttp2_session_send () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
No symbol table info available.
#4 0x00007f9bb059a9b9 in send_loop (session=0x7f9ba04cf190) at h2_proxy_session.c:1517
rv = <optimized out>
#5 h2_proxy_session_process (session=0x7f9ba04cf190) at h2_proxy_session.c:1553
status = <optimized out>
have_written = 0
have_read = 0
run_loop = <optimized out>
#6 0x00007f9bb059db44 in ctx_run (ctx=0x7f9ba06014e0) at mod_proxy_http2.c:258
status = 0
h2_front = <optimized out>
status = <optimized out>
h2_front = <optimized out>
out = <optimized out>
#7 proxy_http2_handler (r=<optimized out>, worker=<optimized out>, conf=<optimized out>, url=<optimized out>, proxyname=<optimized out>, proxyport=<optimized out>) at mod_proxy_http2.c:405
proxy_func = <optimized out>
locurl = 0x7f9ba0601610 "/dns-query?dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB"
u = <optimized out>
slen = <optimized out>
is_ssl = <optimized out>
status = 0
ctx = 0x7f9ba06014e0
uri = {scheme = 0x7f9ba0601580 "h2", hostinfo = 0x7f9ba0601588 "doh.geekwu.org:5343", user = 0x0, password = 0x0, hostname = 0x7f9ba06015a0 "doh.geekwu.org", port_str = 0x7f9ba06015b0 "5343", path = 0x7f9ba06015b8 "/dns-query",
query = 0x7f9ba06015c8 "dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB", fragment = 0x0, hostent = 0x0, port = 5343, is_initialized = 1, dns_looked_up = 0, dns_resolved = 0}
reconnects = <optimized out>
run_connect = <optimized out>
#8 0x00007f9bb0538943 in proxy_run_scheme_handler (r=r@entry=0x7f9ba05910a0, worker=0x7f9bb15cbbb0, conf=conf@entry=0x7f9bb15cba08,
url=0x7f9ba060134e "h2://doh.geekwu.org:5343/dns-query?dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB", proxyhost=proxyhost@entry=0x0, proxyport=proxyport@entry=0) at mod_proxy.c:3437
pHook = <optimized out>
n = 3
rv = -1
#9 0x00007f9bb053a9d2 in proxy_handler (r=0x7f9ba05910a0) at mod_proxy.c:1510
url = 0x7f9ba060134e "h2://doh.geekwu.org:5343/dns-query?dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB"
uri = 0x7f9ba060134e "h2://doh.geekwu.org:5343/dns-query?dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB"
scheme = 0x7f9ba0601470 "h2"
p = <optimized out>
p2 = 0x7f9ba0208300 "(\200 \240\233\177"
sconf = <optimized out>
conf = 0x7f9bb15cba08
proxies = 0x7f9bb15cbac8
ents = 0x7f9bb05b4688
i = <optimized out>
rc = <optimized out>
access_status = 0
direct_connect = <optimized out>
str = <optimized out>
maxfwd = <optimized out>
balancer = 0x0
worker = 0x7f9bb15cbbb0
attempts = 0
max_attempts = 0
list = <optimized out>
saved_status = <optimized out>
#10 0x0000556306b489d0 in ap_run_handler (r=r@entry=0x7f9ba05910a0) at config.c:169
pHook = <optimized out>
n = 1
rv = -1
#11 0x0000556306b48fc6 in ap_invoke_handler (r=r@entry=0x7f9ba05910a0) at config.c:443
handler = <optimized out>
p = <optimized out>
result = 0
old_handler = 0x7f9bb054930b "proxy-server"
ignore = <optimized out>
#12 0x0000556306b619db in ap_process_async_request (r=r@entry=0x7f9ba05910a0) at http_request.c:452
c = 0x7f9ba06430a0
access_status = 0
#13 0x0000556306b61c1e in ap_process_request (r=r@entry=0x7f9ba05910a0) at http_request.c:487
bb = 0x7f9ba06434b0
b = <optimized out>
c = 0x7f9ba06430a0
rv = <optimized out>
#14 0x00007f9bb116bbe6 in c2_process (c=0x7f9ba06430a0, conn_ctx=0x7f9ba06434b0) at h2_c2.c:723
cs = 0x7f9ba0643658
tenc = <optimized out>
timeout = <optimized out>
req = 0x7f9ba04f7180
r = 0x7f9ba05910a0
cleanup = <optimized out>
req = <optimized out>
cs = <optimized out>
r = <optimized out>
tenc = <optimized out>
timeout = <optimized out>
cleanup = <optimized out>
#15 h2_c2_hook_process (c=0x7f9ba06430a0) at h2_c2.c:840
ctx = 0x7f9ba06434b0
#16 0x0000556306b52730 in ap_run_process_connection (c=c@entry=0x7f9ba06430a0) at connection.c:42
pHook = <optimized out>
n = 0
rv = -1
#17 0x00007f9bb116c4d7 in h2_c2_process (c2=c2@entry=0x7f9ba06430a0, thread=thread@entry=0x7f9bafdfb0b0, worker_id=<optimized out>) at h2_c2.c:658
conn_ctx = 0x7f9ba06434b0
#18 0x00007f9bb1187567 in slot_run (thread=0x7f9bafdfb0b0, wctx=0x7f9bb0511850) at h2_workers.c:299
slot = 0x7f9bb0511850
workers = 0x7f9bb05110a0
c = 0x7f9ba06430a0
rv = <optimized out>
#19 0x00007f9bb1844ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
ret = <optimized out>
pd = <optimized out>
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140306500486912, 3999667409471690328, 140722438679950, 140722438679951, 140306500484992, 8396800, -3983747864113949096, -3983768835883903400}, mask_was_saved = 0}}, priv = {pad = {
0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
not_first_call = 0
#20 0x00007f9bb1764a2f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95


The request itself seems legit (I can run it without crashing the
server).

The last log entry before 21:29:30 for this query is a few minutes
before the crash :

/var/log/apache2/access.log:37.98.109.173 - - [17/May/2023:21:26:57 +0200] "GET /dns-query?dns=AAABAAABAAAAAAAADHNhZmVicm93c2luZwpnb29nbGVhcGlzA2NvbQAAHAAB HTTP/2.0" 200 103 "-" "-"

At this time, I have 23 ESTABLISHED (no TIME_WAIT) connections from
this IP, with no requests in access log since yesterday ; so I guess
it's a mis-behaving client

Regards,
--
Bastien

Stefan Eissing

unread,
May 18, 2023, 8:50:04 AM5/18/23
to
Did you have an warning message like "AH03516: unexpected NN streams in hold" at that time in out error log?

Bastien Durel

unread,
May 18, 2023, 9:10:10 AM5/18/23
to
Le 18/05/2023 à 14:41, Stefan Eissing a écrit :
> Did you have an warning message like "AH03516: unexpected NN streams in hold" at that time in out error log?

No (grepping AH03516 in *.log returns nothing (nor does "streams in hold"))

--
Bastien Durel

Stefan Eissing

unread,
May 18, 2023, 11:20:04 AM5/18/23
to
Could you get me a full backtrace of all threads?

Stefan Eissing

unread,
May 19, 2023, 12:20:05 PM5/19/23
to
Hi Bastien,

I am looking into the failures of mod_proxy_http2 and seeing an issue with connection reuse and subsequent handling of requests.

Going back to the original issue, do you still see those with mod_h2 v2.0.15? That would be interesting to know.

I do not know if just relying on mod_proxy_http in your setup would be possible. But it could help us isolating issues.

Kind Regards,
Stefan

> Am 19.05.2023 um 15:04 schrieb Bastien Durel <bas...@durel.org>:
> Hello. I got another one in ap_save_brigade()
>
> --
> Bastien
> <output.log.bz2>

Bastien Durel

unread,
May 19, 2023, 1:00:06 PM5/19/23
to
Le 19/05/2023 à 18:11, Stefan Eissing a écrit :
> Hi Bastien,
>
Hello

> I am looking into the failures of mod_proxy_http2 and seeing an issue with connection reuse and subsequent handling of requests.
>
> Going back to the original issue, do you still see those with mod_h2 v2.0.15? That would be interesting to know.
>
No, I had only 2 segfaults since I upgraded to 2.0.15, and none is in
purge_consumed_buckets :

- proxy_pass_brigade
- ap_save_brigade

> I do not know if just relying on mod_proxy_http in your setup would be possible. But it could help us isolating issues.

I don't think so ... The knot-resolver I forward DOH requests to seems
to only support HTTP/2 ; if I change it to https://, dog fails to
resolve on it :

Error [http]: Nameserver returned HTTP 502 (Proxy Error)

Regards,

--
Bastien Durel

Stefan Eissing

unread,
May 22, 2023, 10:40:06 AM5/22/23
to
I just released v2.0.16 <https://github.com/icing/mod_h2/releases/tag/v2.0.16>. It contains a fix in mod_proxy_http2 retry handling. Not sure if this is related to your crashes as I was so far unsuccessful to reproduce those locally. But maybe you'd like to give this a try.

Kind Regards,
Stefan

>
> Regards,
>
> --
> Bastien Durel
>

Bastien Durel

unread,
May 22, 2023, 12:30:05 PM5/22/23
to
Hello,

Thanks. I've compiled and installed v2.0.16.

I "only" had 2 crashes([1][2]) since friday, so I guess I'll have to
monitor a few days to report back.

Thanks for your work,


[1]
#0 0x00007f9bb04650b3 in ssl_io_filter_output (f=0x7f9ba03c68d8, bb=0x7f9ba04a83b8) at ssl_engine_io.c:2008
#1 0x00007f9bb0597999 in proxy_pass_brigade (flush=1, bb=<optimized out>, origin=<optimized out>, p_conn=0x7f9ba03c80a0, bucket_alloc=<optimized out>) at h2_proxy_session.c:218
#2 raw_send (ngh2=<optimized out>, data=<optimized out>, length=70, flags=<optimized out>, user_data=0x7f9ba04a8190) at h2_proxy_session.c:244
#3 0x00007f9bb14a11f9 in nghttp2_session_send () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#4 0x00007f9bb059a9b9 in send_loop (session=0x7f9ba04a8190) at h2_proxy_session.c:1517
#5 h2_proxy_session_process (session=0x7f9ba04a8190) at h2_proxy_session.c:1553
#6 0x00007f9bb059db44 in ctx_run (ctx=0x7f9ba03524d0) at mod_proxy_http2.c:258

[2]
#0 0x00007f9bb04650c5 in ssl_io_filter_output (f=0x7f9ba01388d8, bb=0x7f9ba05613b8) at ssl_engine_io.c:2008
#1 0x00007f9bb0597999 in proxy_pass_brigade (flush=1, bb=<optimized out>, origin=<optimized out>, p_conn=0x7f9ba013a0a0, bucket_alloc=<optimized out>) at h2_proxy_session.c:218
#2 raw_send (ngh2=<optimized out>, data=<optimized out>, length=74, flags=<optimized out>, user_data=0x7f9ba0561190) at h2_proxy_session.c:244
#3 0x00007f9bb14a11f9 in nghttp2_session_send () from /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#4 0x00007f9bb059a9b9 in send_loop (session=0x7f9ba0561190) at h2_proxy_session.c:1517
#5 h2_proxy_session_process (session=0x7f9ba0561190) at h2_proxy_session.c:1553
#6 0x00007f9bb059db44 in ctx_run (ctx=0x7f9ba014c4d0) at mod_proxy_http2.c:258

--
Bastien

Stefan Eissing

unread,
May 24, 2023, 9:00:05 AM5/24/23
to
I continue to improve mod_proxy_http2: https://github.com/icing/mod_h2/releases/tag/v2.0.17

Added more edge case tests for the module, fixed observed bugs. But have not replicated your crashes which look weird. Sorry.

Kind Regards,
Stefan

> Am 23.05.2023 um 19:30 schrieb Bastien Durel <bas...@durel.org>:
>
> Le 22/05/2023 à 18:18, Bastien Durel a écrit :
>>> I just released v2.0.16
>>> <https://github.com/icing/mod_h2/releases/tag/v2.0.16>. It contains a
>>> fix in mod_proxy_http2 retry handling. Not sure if this is related to
>>> your crashes as I was so far unsuccessful to reproduce those locally.
>>> But maybe you'd like to give this a try.
>> Hello,
>> Thanks. I've compiled and installed v2.0.16.
>> I "only" had 2 crashes([1][2]) since friday, so I guess I'll have to
>> monitor a few days to report back.
>> Thanks for your work,
> Hello.
>
> I got 3 cores today, with /usr/lib/apache2/modules/mod_proxy_http2_2.0.16.so & /usr/lib/apache2/modules/mod_http2_2.0.16.so loaded
>
> here are the backtraces
>
> Regards,
>
> --
> Bastien Durel
> <output.2446989.txt><output.2468671.txt><output.2483382.txt>

Bastien Durel

unread,
May 24, 2023, 10:20:05 AM5/24/23
to
Le mercredi 24 mai 2023 à 14:50 +0200, Stefan Eissing a écrit :
> I continue to improve mod_proxy_http2:
> https://github.com/icing/mod_h2/releases/tag/v2.0.17
>
> Added more edge case tests for the module, fixed observed bugs. But
> have not replicated your crashes which look weird. Sorry.

Hello,

I've put it in use on my server.

Do you need the configuration I use to serve these requests ?

Thanks,

--
Bastien

Stefan Eissing

unread,
May 24, 2023, 1:50:04 PM5/24/23
to
I could use it to try to reproduce, yes.

>
> Thanks,
>
> --
> Bastien
>

root

unread,
May 30, 2023, 6:00:05 AM5/30/23
to
Package: apache2
Version: 2.4.56-1~deb11u2
Followup-For: Bug #1036213


I have additional information that might be related to this bug.
It seems to be following the previous bug I opened in Bug#1033408 ,
which is now solved since 2.4.56-1~deb11u2, but now we don't have
segfaults anymore, but the server of our customer is having a load average
increasing since we've updated the package, we've tested for a week and
load average went from around 5, to 35, slowly increasing over the week
to this value, and it would probably have increased more if we hadn't
intervene.

After witnessing this behavior I noticed these logs in error logs which
I had never seen before:
[...]
[Tue May 30 08:59:29.873462 2023] [http2:warn] [pid 3805413:tid 140434122716928] [client 81.204.51.61:56550] h2_stream(3805413-327-1,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 08:59:29.873486 2023] [http2:warn] [pid 3805413:tid 140434122716928] [client 81.204.51.61:56550] h2_stream(3805413-327-5,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 08:59:29.873490 2023] [http2:warn] [pid 3805413:tid 140434122716928] [client 81.204.51.61:56550] h2_stream(3805413-327-9,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:07:11.128774 2023] [http2:warn] [pid 3808854:tid 140434047182592] [client 106.245.192.226:56994] h2_stream(3808854-230-1,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:07:11.128793 2023] [http2:warn] [pid 3808854:tid 140434047182592] [client 106.245.192.226:56994] h2_stream(3808854-230-5,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:13:36.366838 2023] [http2:warn] [pid 3811558:tid 140434114324224] [client 51.179.98.234:49225] h2_stream(3811558-357-17,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:13:36.366874 2023] [http2:warn] [pid 3811558:tid 140434114324224] [client 51.179.98.234:49225] h2_stream(3811558-357-19,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:55:14.468946 2023] [http2:warn] [pid 3832829:tid 140434089146112] [client 109.234.73.147:53640] h2_stream(3832829-35-5,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[Tue May 30 09:56:14.469032 2023] [http2:warn] [pid 3832829:tid 140434089146112] [client 109.234.73.147:53640] h2_stream(3832829-35-5,CLEANUP): started=1, scheduled=1, ready=0, out_buffer=0
[...]

After noticing these, I immediately thought about the previous bug and
completely disabled the http2 module in apache. It immediately solved
the load issue.
I know it's very few information and I'm not sure it's related exactly
to his particular bug, might need a bug report of its own, but in case,
I don't want to duplicate and will let you choose.



-- Package-specific info:

-- System Information:
Debian Release: 11.7
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable-security'), (500, 'stable')
Architecture: amd64 (x86_64)

Kernel: Linux 5.10.0-18-amd64 (SMP w/32 CPU threads)
Locale: LANG=fr_FR.UTF-8, LC_CTYPE=fr_FR.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages apache2 depends on:
ii apache2-bin 2.4.56-1~deb11u2
ii apache2-data 2.4.56-1~deb11u2
ii apache2-utils 2.4.56-1~deb11u2
ii dpkg 1.20.12
ii init-system-helpers 1.60
ii lsb-base 11.1.0
ii mime-support 3.66
ii perl 5.32.1-4+deb11u2
ii procps 2:3.3.17-5

Versions of packages apache2 recommends:
ii ssl-cert 1.1.0+nmu1

Versions of packages apache2 suggests:
pn apache2-doc <none>
pn apache2-suexec-pristine | apache2-suexec-custom <none>
ii lynx [www-browser] 2.9.0dev.6-3~deb11u1

Versions of packages apache2-bin depends on:
ii libapr1 1.7.0-6+deb11u2
ii libaprutil1 1.6.1-5+deb11u1
ii libaprutil1-dbd-sqlite3 1.6.1-5+deb11u1
ii libaprutil1-ldap 1.6.1-5+deb11u1
ii libbrotli1 1.0.9-2+b2
ii libc6 2.31-13+deb11u6
ii libcrypt1 1:4.4.18-4
ii libcurl4 7.74.0-1.3+deb11u7
ii libjansson4 2.13.1-1.1
ii libldap-2.4-2 2.4.57+dfsg-3+deb11u1
ii liblua5.3-0 5.3.3-1.1+b1
ii libnghttp2-14 1.43.0-1
ii libpcre3 2:8.44-2+0~20210301.9+debian11~1.gbpa278ad
ii libssl1.1 1.1.1n-0+deb11u4
ii libxml2 2.9.14+dfsg-0.1+0~20230421.14+debian11~1.gbpf14485
ii perl 5.32.1-4+deb11u2
ii zlib1g 1:1.2.11.dfsg-2+deb11u2

Versions of packages apache2-bin suggests:
pn apache2-doc <none>
pn apache2-suexec-pristine | apache2-suexec-custom <none>
ii lynx [www-browser] 2.9.0dev.6-3~deb11u1

Versions of packages apache2 is related to:
ii apache2 2.4.56-1~deb11u2
ii apache2-bin 2.4.56-1~deb11u2

-- Configuration Files:
/etc/apache2/apache2.conf changed [not included]
/etc/apache2/mods-available/mpm_event.conf changed [not included]
/etc/apache2/ports.conf changed [not included]
/etc/apache2/sites-available/000-default.conf changed [not included]

-- no debconf information

Stefan Eissing

unread,
May 30, 2023, 10:30:04 AM5/30/23
to
Thanks for the information.

Does this setup also run mod_proxy_http2? (I am investigating issue in that module that I can somewhat reproduce)
What measurement is the "load average" you mentioned? CPU usage?

As to the observed log entries, these appear when a client connection is terminated and the HTTP/2 processing waits on running H2 workers to react to an abort and stop processing. All stream (e.g. running workers) that do not return after 60 seconds are logged and the waiting continues. After another 60 seconds all remaining are logged again and so on.

So if these entries for a particular connection (you see in the "h2_stream(3805413-327-1" that it is in process 3805413 connection 327 and stream id 1)
continue to be logged every minute, this points to a server mistake. If the logging of such stream stops eventually, this points to badly reacting request processing and it is the question what is running in your server that takes this long to finish/react to an aborted connection).

For example, if you proxy a backend with very long timeout and that backend does not respond, these entries may happen.

tl;dr

The log entries could be a server bug, but as well a matter of configuration.

Kind Regards,
Stefan

Fabien LE BERRE

unread,
May 30, 2023, 10:50:04 AM5/30/23
to
Hi,

this setup does not run mod_proxy_http2. Only mod_http2 was enabled.
Semantic is quite important as CPU Usage isn't really "load average", but I will just give you a link for the "load average" question which will explain it better than I will ever do ;) : https://en.wikipedia.org/wiki/Load_(computing)

We do have a varnish behind apache with KeepAlive being disabled. So it might be related to this application behind apache as well, not surprised as the previous "segfault" bug I was refering to, was noticed on maybe 3 or 4 servers, while we manage hundreds of them, so it might be dependant to how they handle connections/pipe...
I'm asking, just in case is keepalive necessary with http2 ?

Regards,
Fabien
--
Fabien Le Berre Homme de la situation
01 86 95 54 04 - 37 rue des Mathurins - 75008 Paris 

Stefan Eissing

unread,
May 31, 2023, 7:20:05 AM5/31/23
to
Hi Bastien,

I was finally able to reproduce here what looks like the crashes you see with mod_proxy_http2 (notice the careful wording). And I fixed it in https://github.com/icing/mod_h2/releases/tag/v2.0.18

Looking forward to hear how it fares on your system.

Kind Regards,
Stefan

Bastien Durel

unread,
May 31, 2023, 8:00:04 AM5/31/23
to
Le 31/05/2023 à 13:15, Stefan Eissing a écrit :
> Hi Bastien,
>
> I was finally able to reproduce here what looks like the crashes you see with mod_proxy_http2 (notice the careful wording). And I fixed it in https://github.com/icing/mod_h2/releases/tag/v2.0.18
>
> Looking forward to hear how it fares on your system.
>
Hello,

Thanks for your work. I've put it on my system, I'll report any new
crash (last week I got approximately one every 2 days)

Regards,

--
Bastien Durel

Bastien Durel

unread,
Jun 8, 2023, 6:10:05 AM6/8/23
to
Le mercredi 31 mai 2023 à 13:15 +0200, Stefan Eissing a écrit :
> Hi Bastien,
>
> I was finally able to reproduce here what looks like the crashes you
> see with mod_proxy_http2 (notice the careful wording). And I fixed it
> in https://github.com/icing/mod_h2/releases/tag/v2.0.18
>
> Looking forward to hear how it fares on your system.
>
Hello,

After a week running on my system, I did not got any crash at all.

So maybe you effectively found and fix the problem I saw :)

Regards,

--
Bastien

Stefan Eissing

unread,
Jun 8, 2023, 6:10:05 AM6/8/23
to
Great! Thanks for reporting back. I'll make sure that the fix is part of our next release.
0 new messages