diagnosis and remedy of stuck and accumulating Apache processes

Symptom:

Apache tasks growing in count, reaching limit, causing DOS. 750 is the critical number on this host.

● apache2.service - The Apache HTTP Server
     Loaded: loaded (/lib/systemd/system/apache2.service; enabled; preset: enabled)
     Active: active (running) since Mon 2026-02-02 13:01:20 UTC; 4h 35min ago
       Docs: https://httpd.apache.org/docs/2.4/
    Process: 1743790 ExecStart=/usr/sbin/apachectl start (code=exited, status=0/SUCCESS)
   Main PID: 1743795 (apache2)
      Tasks: 751

Diagnostics:

Using mod_status, we can see lots of tasks hanging with status “closing” for thousands of seconds:

1756434	1/1/137	C	0.00	9886	1	16641	6.0	0.01	0.91	123.123.123.123	http/1.1	myhost.co.uk:443	GET /cgi-bin/koha/opac-ISBDdetail.pl?biblionumber=12345678 HTTP/

Apache mod_status’s category “closing” is not very descriptive though. It tells us nothing of what is holding the process up, especially where forking is concerned. ps called on that PID with wchan (waiting channel, or “wtf are you waiting for”) reports:

root@HOST:/home/koha # ps -p 1756434 -o pid,etime,stat,wchan:25,cmd
    PID     ELAPSED STAT WCHAN                     CMD
1756434    02:29:32 Sl   do_wait                   /usr/sbin/apache2 -k start

do_wait. It’s waiting for a child to terminate. Use pstree to see children:

root@HOST:/home/koha # pstree -p 1756434
apache2(1756434)─┬─apache2(1756447)
                 ├─{apache2}(1756435)
                 ├─{apache2}(1756439)
                 └─{apache2}(1756444)

The only child process, 1756447, has a waiting channel value of futex_wait_queue:

root@HOST:/home/koha # ps -p 1756447 -o pid,etime,stat,wchan:25,cmd

    PID     ELAPSED STAT WCHAN                     CMD
1756447    04:19:14 S    futex_wait_queue          /usr/sbin/apache2 -k start

futex = “fast userspace mutex”, a userland lock queue. So we have children stuck waiting for some kind of userland lock, and parents waiting for children. Using ps again to count instances of these two wchan values, we get:

root@HOST:/home/koha# ps -C apache2 -o wchan:20 | tail -n +2 | sort | uniq -c | sort -nr
     45 futex_wait_queue
     45 do_wait
     12 futex_lock_pi
      1 do_select
      1 do_epoll_wait

Exactly 1:1 for each of the above parent/child wchan statuses, implying this is happening exactly once for every stuck parent! So, what the fucking shit are these children waiting around for? cat stack just says “futex”:

root@HOST:/home/koha# cat /proc/1756447/stack
[<0>] futex_wait_queue+0x60/0x90
[<0>] futex_wait+0x185/0x270
[<0>] do_futex+0x106/0x1b0
[<0>] __x64_sys_futex+0x8e/0x1d0
[<0>] do_syscall_64+0x55/0x80
[<0>] entry_SYSCALL_64_after_hwframe+0x6e/0xd8

So, install an actual debugger and ask an LLM how to use it. Then, from the stack of the hung child, we get:

root@HOST:/home/koha# gdb -p 1756447 -batch -ex "thread apply all bt"
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
futex_wait (private=0, expected=2, futex_word=0x55a629efde08) at ../sysdeps/nptl/futex-internal.h:146
146	../sysdeps/nptl/futex-internal.h: No such file or directory.

Thread 1 (Thread 0x7f367a769780 (LWP 1756447) "apache2"):
#0  futex_wait (private=0, expected=2, futex_word=0x55a629efde08) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x55a629efde08, private=0) at ./nptl/lowlevellock.c:49
#2  0x00007f367a86b482 in lll_mutex_lock_optimized (mutex=0x55a629efde08) at ./nptl/pthread_mutex_lock.c:48
#3  ___pthread_mutex_lock (mutex=0x55a629efde08) at ./nptl/pthread_mutex_lock.c:93
#4  0x00007f367a4b679f in log4shib::Category::removeAllAppenders() () from target:/lib/x86_64-linux-gnu/liblog4shib.so.2
#5  0x00007f367a4b84ea in log4shib::HierarchyMaintainer::shutdown() () from target:/lib/x86_64-linux-gnu/liblog4shib.so.2
#6  0x00007f367a4b886c in log4shib::HierarchyMaintainer::~HierarchyMaintainer() () from target:/lib/x86_64-linux-gnu/liblog4shib.so.2
#7  0x00007f367a81d55d in __run_exit_handlers (status=0, listp=0x7f367a9b2820 <__exit_funcs>, run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true) at ./stdlib/exit.c:116
#8  0x00007f367a81d69a in __GI_exit (status=<optimized out>) at ./stdlib/exit.c:146
#9  0x00007f367a5f8278 in itk_fork_process () from target:/usr/lib/apache2/modules/mpm_itk.so
#10 0x000055a5eec7dfd0 in ap_run_process_connection ()
#11 0x00007f367a5d1ca4 in ?? () from target:/usr/lib/apache2/modules/mod_mpm_prefork.so
#12 0x00007f367a5d2027 in ?? () from target:/usr/lib/apache2/modules/mod_mpm_prefork.so
#13 0x00007f367a5d2929 in ?? () from target:/usr/lib/apache2/modules/mod_mpm_prefork.so
#14 0x000055a5eec546e0 in ap_run_mpm ()
#15 0x000055a5eec4c1c2 in main ()
[Inferior 1 (process 1756447) detached]

Mmmmmkayyyy! log4shib is holding a lock which prevents the child, and thus the parent, from exiting cleanly forever, or until you bounce Apache. This isn’t Apache holding onto connections for too long, it’s murking them after a sensible period but being thwarted by a mutex.

Using the virtual memory address of the offending futex from the above trace, we can do:

root@HOST:/home/koha # gdb -p 1756447 -batch \
  -ex "p *(pthread_mutex_t*)0x55a629efde08" \
  -ex "p ((pthread_mutex_t*)0x55a629efde08)->__data.__owner" \
  -ex "p ((pthread_mutex_t*)0x55a629efde08)->__data.__lock"
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
futex_wait (private=0, expected=2, futex_word=0x55a629efde08) at ../sysdeps/nptl/futex-internal.h:146
146	../sysdeps/nptl/futex-internal.h: No such file or directory.
$1 = {__data = {__lock = 2, __count = 0, __owner = 1756444, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = "\002\000\000\000\000\000\000\000\034\315\032\000\001", '\000' <repeats 26 times>, __align = 2}
$2 = 1756444
$3 = 2
[Inferior 1 (process 1756447) detached]

This is dope. It gives us specific field values from that stuck mutex. Namely:

Looking back at the pstree for this parent/Apache task, we see that 1756444 is a thread of the parent, 1756434:

root@HOST:/home/koha # pstree -p 1756434
apache2(1756434)─┬─apache2(1756447)
                 ├─{apache2}(1756435)
                 ├─{apache2}(1756439)
                 └─{apache2}(1756444)

So. 435, 439 and 444 are threads of the parent, 434. 447 is a child of 434 and has no threads other than its primary one. In 447, the mutex says __owner = 1756444. That owner value 1756444 is the thread ID (TID) of the thread that locked the mutex. After a multithreaded process calls fork(), only the thread that called fork() exists in the child process. Any mutex locked by a different thread in the parent process at the time of the fork remains locked in the child though, and the __owner value is the TID of a thread that does not exist in the child. This is a deadlock, and it is preventing the cleanup functions in log4shib from running, which stops the execution of exit(), and hangs the task.

This is the affected function from log4shib, not that this actually helps us very much:

    void Category::removeAllAppenders() {
        threading::ScopedLock lock(_appenderSetMutex);
        {
            for (AppenderSet::iterator i = _appender.begin();
                 i != _appender.end(); i++) {
                // found
                OwnsAppenderMap::iterator i2;
                if (ownsAppender(*i, i2)) {
                    delete (*i);
                }
            }

            _ownsAppender.clear();
            _appender.clear();
        }
    }

https://salsa.debian.org/shib-team/log4shib

This function is called as part of the “destructor”/cleanup routine. I ain’t fixing any of this the proper way though, so onward we go.

TL;DR - what’s happening and what do we do?

The upshot is a dead Apache task that will not ever release its slot. Now we just need to prevent this.

We do modify shibd’s logging behaviour a bit when we install it - increasing log verbosity. The extra debug logging is not the cause of the deadlock, but probably an accelerator/probability embiggener. The more often the parent must hold the lock, the greater the chance of a child inheriting it by accident. I downloaded and extracted the original logger config files from the shibboleth-sp-common Debian package and did a diff against the ones on the afflicted host - this is that, in case we find it useful later.

root@HOST:/home/koha # diff shibd.logger /etc/shibboleth/shibd.logger
2c2
< log4j.rootCategory=INFO, shibd_log, warn_log
---
> log4j.rootCategory=DEBUG, shibd_log, warn_log
5,9c5,9
< log4j.category.XMLTooling.XMLObject=INFO
< log4j.category.XMLTooling.XMLObjectBuilder=INFO
< log4j.category.XMLTooling.KeyInfoResolver=INFO
< log4j.category.Shibboleth.IPRange=INFO
< log4j.category.Shibboleth.PropertySet=INFO
---
> log4j.category.XMLTooling.XMLObject=DEBUG
> log4j.category.XMLTooling.XMLObjectBuilder=DEBUG
> log4j.category.XMLTooling.KeyInfoResolver=DEBUG
> log4j.category.Shibboleth.IPRange=DEBUG
> log4j.category.Shibboleth.PropertySet=DEBUG
12c12
< log4j.category.XMLTooling.libcurl=INFO
---
> log4j.category.XMLTooling.libcurl=DEBUG
31c31
< log4j.category.XMLTooling.Signature.Debugger=INFO, sig_log
---
> log4j.category.XMLTooling.Signature.Debugger=DEBUG, sig_log
37c37
< log4j.category.Shibboleth-TRANSACTION=INFO, tran_log
---
> log4j.category.Shibboleth-TRANSACTION=DEBUG, tran_log
 
 

root@HOST:/home/koha # diff console.logger /etc/shibboleth/console.logger
1c1
< log4j.rootCategory=WARN, console
---
> log4j.rootCategory=DEBUG, console
4,8c4,8
< log4j.category.XMLTooling.XMLObject=INFO
< log4j.category.XMLTooling.XMLObjectBuilder=INFO
< log4j.category.XMLTooling.KeyInfoResolver=INFO
< log4j.category.Shibboleth.IPRange=INFO
< log4j.category.Shibboleth.PropertySet=INFO
---
> log4j.category.XMLTooling.XMLObject=DEBUG
> log4j.category.XMLTooling.XMLObjectBuilder=DEBUG
> log4j.category.XMLTooling.KeyInfoResolver=DEBUG
> log4j.category.Shibboleth.IPRange=DEBUG
> log4j.category.Shibboleth.PropertySet=DEBUG
11c11
< log4j.category.XMLTooling.libcurl=INFO
---
> log4j.category.XMLTooling.libcurl=DEBUG
 
 
 

root@HOST:/home/koha # diff native.logger /etc/shibboleth/native.logger
2c2
< log4j.rootCategory=WARN, native_log
---
> log4j.rootCategory=DEBUG, native_log
5,9c5,9
< log4j.category.XMLTooling.XMLObject=WARN
< log4j.category.XMLTooling.XMLObjectBuilder=WARN
< log4j.category.XMLTooling.KeyInfoResolver=WARN
< log4j.category.Shibboleth.IPRange=WARN
< log4j.category.Shibboleth.PropertySet=WARN
---
> log4j.category.XMLTooling.XMLObject=DEBUG
> log4j.category.XMLTooling.XMLObjectBuilder=DEBUG
> log4j.category.XMLTooling.KeyInfoResolver=DEBUG
> log4j.category.Shibboleth.IPRange=DEBUG
> log4j.category.Shibboleth.PropertySet=DEBUG

I have now set them back to the defaults.

If this log level reduction helps but doesn’t get us quite far enough, I’ll further reduce shibd logging from the defaults. What makes this failure mode possible is the existence of multithreading in the parent before the fork, but I think this would require a local patch to log4shib to actually fix.

HAMMER: a manual reaper for these processes, not reliant on mod_status and not reliant on attaching a debugger

The easiest way to identify Apache parent tasks and their children which are irrevocably stuck on one of these deadlocks is to use mod_status and look for any tasks with status “closing” that has an SS value in the thousands of seconds. SS is approximately “seconds since the current request began”. If that value is over 10,000, and the PID has wchan = do_wait and it has a child with wchan = futex_wait_queue, we can safely conclude it’s stuck. To become absolutely certain during diagnosis, I attached a debugger and compared the PID of the stuck child with the __owner value of the mutex it was stuck trying to touch. This debugger step we can safely forget about though.

Here is a script which looks for the signs of the stickage, waits around for SAMPLE_DELAY seconds to make sure, then murders any processes which seem to be affected.

#!/usr/bin/env bash
set -euo pipefail

PARENT_PID="$(cat /var/run/apache2/apache2.pid 2>/dev/null || true)"
[[ -n "$PARENT_PID" && -d "/proc/$PARENT_PID" ]] || { echo "No apache parent PID"; exit 2; }

# Tune these:
MIN_ELAPSED=1800        # 30 minutes; bump to 3600 if you want ultra-safe
SAMPLE_DELAY=30         # seconds between samples
WCHAN_REGEX='^futex_wait_queue(_me)?$'  # tighten to what you actually see
DRY_RUN="${DRY_RUN:-0}"

# Reads utime+stime from /proc/<pid>/stat (fields 14 and 15)
proc_cputicks() {
  awk '{print $14+$15}' "/proc/$1/stat" 2>/dev/null || echo ""
}

ps_field() { ps -o "$1=" -p "$2" 2>/dev/null | awk '{$1=$1;print}'; }

mapfile -t WORKERS < <(pgrep -P "$PARENT_PID" 2>/dev/null || true)
[[ ${#WORKERS[@]} -gt 0 ]] || { echo "No workers"; exit 0; }

# First sample
declare -A WCHAN1 ET1 CPU1
for pid in "${WORKERS[@]}"; do
  [[ -d "/proc/$pid" ]] || continue
  wchan="$(ps_field wchan "$pid")"
  et="$(ps_field etimes "$pid")"
  cpu="$(proc_cputicks "$pid")"
  WCHAN1["$pid"]="$wchan"
  ET1["$pid"]="$et"
  CPU1["$pid"]="$cpu"
done

sleep "$SAMPLE_DELAY"

# Second sample + decision
KILL=()
for pid in "${WORKERS[@]}"; do
  [[ -d "/proc/$pid" ]] || continue

  w1="${WCHAN1[$pid]-}"
  et1="${ET1[$pid]-0}"
  cpu1="${CPU1[$pid]-}"

  w2="$(ps_field wchan "$pid")"
  et2="$(ps_field etimes "$pid")"
  cpu2="$(proc_cputicks "$pid")"
  cmd="$(ps_field cmd "$pid")"

  # Must be old enough and in the target futex wait both times
  if [[ "$w1" =~ $WCHAN_REGEX ]] && [[ "$w2" =~ $WCHAN_REGEX ]] && [[ "$et2" =~ ^[0-9]+$ ]] && (( et2 >= MIN_ELAPSED )); then
    # CPU must not move (strong signal); if cpu not readable, skip
    if [[ -n "$cpu1" && -n "$cpu2" && "$cpu1" == "$cpu2" ]]; then
      echo "FLAG pid=$pid etimes=$et2 wchan=$w2 cpu_ticks=$cpu2 cmd='$cmd'"
      KILL+=("$pid")
    fi
  fi
done

if [[ ${#KILL[@]} -eq 0 ]]; then
  echo "No stuck workers found."
  exit 0
fi

echo "Will terminate: ${KILL[*]}"
if [[ "$DRY_RUN" == "1" ]]; then
  echo "DRY RUN: not killing."
  exit 0
fi

kill -TERM "${KILL[@]}" 2>/dev/null || true
sleep 2
kill -KILL "${KILL[@]}" 2>/dev/null || true

If encountering this problem, and reducing Shibboleth log verbosity doesn’t help (or you can’t change that), and you don’t have time to be forensic about it, cron this up to run every few minutes. DRY_RUN environment variable to test.