fix(api): stop silent clients from wedging the gunicorn thread pool
On 2026-10-09 (sdbees) both :8000 API workers had 7 of 8 gthread pool
threads blocked in tcp_recvmsg -> sk_wait_data; /health and
/api/blocked-ips hung 40s+ while the container reported healthy.
The app makes no in-process outbound socket reads (every ACME/HAProxy
interaction is an already-bounded subprocess). The blocked reads were
gunicorn gthread reading the CLIENT socket: TConn.init() calls
setblocking(True), i.e. timeout None, before parsing the request. Any
peer that sends a few bytes and goes quiet (a TLS ClientHello on this
plain-HTTP port, scanners; :8000 is published on 0.0.0.0) pins a pool
thread forever. gunicorn --timeout does not catch it (gthread only
watches the main thread's heartbeat), --max-requests never triggers on
a worker that finishes nothing, and socket.setdefaulttimeout() is reset
by setblocking(True).
- haproxy_gunicorn_worker.TimeoutThreadWorker (used for :8000 and :8080):
* per-connection socket timeout HAPROXY_MGR_CLIENT_TIMEOUT (20s),
re-applied on keep-alive reuse; bounds socket I/O, not handling time
* watchdog: if every pool thread has been in the same request for more
than HAPROXY_MGR_WEDGE_SECONDS (1200s, > certbot renew's 900s), dump
all thread stacks and exit so the master respawns the worker
* client timeouts logged as one INFO line, not a traceback
- haproxy_manager: socket.setdefaulttimeout (HAPROXY_MGR_SOCKET_DEFAULT_TIMEOUT,
60s) as defence in depth for any future in-process client; /health now
reports the answering worker's busy/total threads and oldest request age
- scripts/healthcheck.sh: probes :8000/health (4s) AND :80; image
HEALTHCHECK uses it (WHP's --health-cmd override must too)
- scripts/test-gunicorn-socket-timeouts.py (12 tests, real gunicorn),
added to the Docker build gate
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
1 parent
e134b2b234
commit
0ce144d2fb
8 files changed
+654
-10
No files matched your search
@@ -10,6 +10,7 @@ This file provides guidance to Claude Code (claude.ai/code) when working with co
|
||||
- **Stick-table contract**: `python3 scripts/test-stick-table-contract.py` - offline; holds the templates' `store` clauses, `STICK_TABLE_FIELD_CONTRACT`, and every consumer to each other. Run it after touching any `stick-table` line.
|
||||
- **Runtime-map contract**: `python3 scripts/test-runtime-map-contract.py` - offline; asserts the runtime map commands are `@1`-prefixed, reference the map by FILE PATH (never `#<id>`), carry the value `1`, and that every captured rejection is classified as a failure. Run it after touching any `add map`/`del map`/`clear map` path.
|
||||
- **Certificate destruction safety**: `python3 scripts/test-cert-write-safety.py` - offline; asserts a live `.pem` is never truncated, removed, or its certbot lineage deleted while any configured domain still references it (one bundle serves many names, so `ssl_cert_path` is routinely shared). Run it after touching any `os.remove`/`certbot delete`/PEM-write path.
|
||||
- **API thread-pool safety**: `python3 scripts/test-gunicorn-socket-timeouts.py` - runs REAL gunicorn (~30s); asserts a silent/half-written client cannot pin a gthread pool thread (per-connection socket timeout, `HAPROXY_MGR_CLIENT_TIMEOUT`), slow legit requests are not cut off, the wedge watchdog (`HAPROXY_MGR_WEDGE_SECONDS`) replaces a fully stuck worker, and an in-process call to a stalled upstream times out. Run it after touching `haproxy_gunicorn_worker.py`, start-up.sh's gunicorn lines, or upgrading gunicorn (the worker overrides `ThreadWorker.enqueue_req`).
|
||||
- **Manual Testing**: Run `curl` commands against `http://localhost:8000` endpoints as shown in README.md
|
||||
|
||||
### Reading stick tables (and why it is easy to get silently wrong)
|
||||
@@ -166,6 +167,7 @@ re-reads it on reload, so a failed runtime command must degrade to
|
||||
- Exposes ports 80 (HTTP), 443 (HTTPS), and 8000 (management API/UI)
|
||||
- Stats page on port 8404 (localhost only inside container)
|
||||
- Management interface on port 8000 should be firewall-protected in production
|
||||
- Dockerfile HEALTHCHECK verifies both port 8000 (Flask API) and port 80 (HAProxy), with `start-period=60s` and `timeout=10s`
|
||||
- Dockerfile HEALTHCHECK runs `scripts/healthcheck.sh`: port 8000 `/health` (4s max) AND port 80 (HAProxy). WHP's `lib-edge-container.sh` passes its own `--health-cmd`, which REPLACES the image's; it must call `/haproxy/scripts/healthcheck.sh` or the fleet never probes :8000
|
||||
- gunicorn uses `haproxy_gunicorn_worker.TimeoutThreadWorker` (gthread + client socket timeout + wedge watchdog). Stock gthread leaves client sockets blocking with NO timeout; `--timeout` only watches the main thread's heartbeat
|
||||
- Supports deployment on servers with git directory at `/root/whp` and web file sync via rsync to `/docker/whp/web/`
|
||||
- HAProxy is version 3.0.11
|
||||
+8
-3
@@ -44,6 +44,7 @@ WORKDIR /haproxy
|
||||
COPY ./templates /haproxy/templates
|
||||
COPY requirements.txt /haproxy/
|
||||
COPY haproxy_manager.py /haproxy/
|
||||
COPY haproxy_gunicorn_worker.py /haproxy/
|
||||
COPY scripts /haproxy/scripts
|
||||
COPY trusted_ips.list /etc/haproxy/trusted_ips.list
|
||||
COPY trusted_ips.map /etc/haproxy/trusted_ips.map
|
||||
@@ -92,7 +93,8 @@ RUN python3 /haproxy/scripts/test-wpadmin-gate.py \
|
||||
&& python3 /haproxy/scripts/test-config-rollback.py \
|
||||
&& python3 /haproxy/scripts/test-cert-write-safety.py \
|
||||
&& python3 /haproxy/scripts/test-cert-scripts.py \
|
||||
&& python3 /haproxy/scripts/validate-rendered-config.py
|
||||
&& python3 /haproxy/scripts/validate-rendered-config.py \
|
||||
&& python3 /haproxy/scripts/test-gunicorn-socket-timeouts.py
|
||||
# Create log directories
|
||||
RUN mkdir -p /var/log && touch /var/log/haproxy-manager.log /var/log/haproxy-manager-errors.log
|
||||
RUN chmod 755 /var/log/haproxy-manager.log /var/log/haproxy-manager-errors.log
|
||||
@@ -105,7 +107,10 @@ RUN mkdir -p /var/spool/cron/crontabs && \
|
||||
# 443/udp carries HTTP/3 (QUIC). EXPOSE is documentation only — the container
|
||||
# must still be run with `-p 443:443/udp` for the UDP listener to be reachable.
|
||||
EXPOSE 80 443 443/udp 8000
|
||||
# Add health check
|
||||
# Health check: management API (:8000, short timeout) AND HAProxy (:80).
|
||||
# See scripts/healthcheck.sh. NOTE: WHP's lib-edge-container.sh passes its own
|
||||
# --health-cmd, which REPLACES this one on deployed hosts; it must be pointed
|
||||
# at /haproxy/scripts/healthcheck.sh for the fleet to get the :8000 probe.
|
||||
HEALTHCHECK --interval=30s --timeout=10s --start-period=60s --retries=3 \
|
||||
CMD curl -sf --max-time 5 http://localhost:8000/health && curl -s --max-time 5 -o /dev/null http://localhost/ || exit 1
|
||||
CMD /haproxy/scripts/healthcheck.sh
|
||||
CMD ["/haproxy/scripts/start-up.sh"]
|
||||
@@ -0,0 +1,209 @@
|
||||
"""gunicorn gthread worker that cannot be wedged by a silent client.
|
||||
|
||||
Incident 2026-10-09 (sdbees), and very likely the 2026-07-07 whp01 one too
|
||||
-------------------------------------------------------------------------
|
||||
Both :8000 API workers had 7 of 8 pool threads parked in the kernel in
|
||||
``tcp_recvmsg -> sk_wait_data``: a blocking socket read with no timeout.
|
||||
/health and /api/blocked-ips hung for 40s+, the container stayed "healthy".
|
||||
|
||||
haproxy_manager.py makes NO in-process outbound network reads (no requests,
|
||||
urllib, http.client, raw socket or ssl client anywhere; every ACME/HAProxy
|
||||
interaction is a subprocess, already bounded since 2026.07.3). The reads that
|
||||
blocked were gunicorn's own reads of the CLIENT socket:
|
||||
|
||||
gunicorn/workers/gthread.py TConn.init(): self.sock.setblocking(True)
|
||||
|
||||
Once the main loop sees a connection become readable it hands it to a pool
|
||||
thread and turns the socket fully blocking -- timeout None -- before parsing
|
||||
the request. Any peer that sends a few bytes and then waits (a TLS ClientHello
|
||||
sent to this plain-HTTP port, a port scanner, a half-written request, a body
|
||||
shorter than its Content-Length) pins that pool thread forever. :8000 is
|
||||
published on 0.0.0.0 by the deploy (`-p 8000:8000`, which bypasses firewalld),
|
||||
and on sdbees internet scanners were measured connecting to it. Each such
|
||||
connection leaks one thread; 4 per worker exhausts the pool.
|
||||
|
||||
gunicorn's --timeout does not catch this: for gthread it only checks that the
|
||||
worker's MAIN thread keeps heart-beating, and the main thread keeps polling
|
||||
happily while every pool thread is stuck. --max-requests does not help either:
|
||||
a worker whose threads never finish a request never reaches the limit.
|
||||
socket.setdefaulttimeout() does not help: setblocking(True) explicitly resets
|
||||
the timeout to None, overriding any default.
|
||||
|
||||
What this worker changes (and nothing else)
|
||||
-------------------------------------------
|
||||
1. Every client connection gets an explicit socket timeout
|
||||
(HAPROXY_MGR_CLIENT_TIMEOUT, default 20s) at the exact point gthread makes it
|
||||
blocking. It bounds each recv/send on the client socket -- request line,
|
||||
headers, the body the app reads, and response writes. It does NOT bound how
|
||||
long the app takes to handle a request (a long certbot run is a subprocess
|
||||
with its own timeout and touches the client socket only once it is done).
|
||||
A stalled peer now costs one thread for at most that long, then the
|
||||
connection is closed and the thread is returned to the pool.
|
||||
|
||||
2. A per-worker watchdog thread (HAPROXY_MGR_WEDGE_SECONDS, default 1200s; 0
|
||||
disables). If EVERY pool thread has been inside the same request for longer
|
||||
than that -- i.e. the pool has not turned over at all for 20 minutes, longer
|
||||
than the slowest legitimate request (certbot renew, 900s) -- the worker logs
|
||||
every thread's Python stack to the error log and exits. The gunicorn master
|
||||
respawns it in about a second, without touching HAProxy or the edge.
|
||||
This is a backstop for blocking sources we have not found yet; the fix for
|
||||
the known one is (1).
|
||||
|
||||
3. pool_status() exposes busy/total threads and the oldest in-flight age so
|
||||
/health can report saturation.
|
||||
"""
|
||||
|
||||
import errno
|
||||
import logging
|
||||
import os
|
||||
import sys
|
||||
import threading
|
||||
import time
|
||||
import traceback
|
||||
|
||||
from gunicorn.workers.gthread import ThreadWorker
|
||||
|
||||
|
||||
def _env_float(name, default):
|
||||
try:
|
||||
return float(os.environ.get(name, default))
|
||||
except (TypeError, ValueError):
|
||||
return float(default)
|
||||
|
||||
|
||||
CLIENT_TIMEOUT = _env_float('HAPROXY_MGR_CLIENT_TIMEOUT', 20)
|
||||
WEDGE_SECONDS = _env_float('HAPROXY_MGR_WEDGE_SECONDS', 1200)
|
||||
WATCHDOG_INTERVAL = _env_float('HAPROXY_MGR_WATCHDOG_INTERVAL', 15)
|
||||
|
||||
# Exit status for a watchdog-killed worker. Must NOT be 3 (WORKER_BOOT_ERROR)
|
||||
# or 4 (APP_LOAD_ERROR): on those the gunicorn master halts the whole server
|
||||
# instead of respawning the worker.
|
||||
WEDGED_EXIT_CODE = 1
|
||||
|
||||
_current_worker = None
|
||||
|
||||
|
||||
def pool_status():
|
||||
"""Busy/total threads of the worker serving the caller, or None when the
|
||||
app is not running under this worker class (e.g. tests, dev server)."""
|
||||
w = _current_worker
|
||||
if w is None:
|
||||
return None
|
||||
return w.pool_status()
|
||||
|
||||
|
||||
class _QuietClientTimeout(logging.Filter):
|
||||
"""gthread logs any OSError without an errno it recognises as
|
||||
log.exception("Socket error processing request.") -- a full traceback.
|
||||
A client timeout is now an expected, bounded event (scanners hit this port
|
||||
constantly), so reduce it to one line instead of flooding the error log."""
|
||||
|
||||
def filter(self, record):
|
||||
exc = record.exc_info[1] if record.exc_info else None
|
||||
if isinstance(exc, TimeoutError) and \
|
||||
str(record.msg).startswith('Socket error processing request'):
|
||||
record.msg = ('Closed client connection idle for more than %ss '
|
||||
'(HAPROXY_MGR_CLIENT_TIMEOUT)' % CLIENT_TIMEOUT)
|
||||
record.args = ()
|
||||
record.exc_info = None
|
||||
record.exc_text = None
|
||||
record.levelno = logging.INFO
|
||||
record.levelname = 'INFO'
|
||||
return True
|
||||
|
||||
|
||||
class TimeoutThreadWorker(ThreadWorker):
|
||||
"""gthread worker whose client sockets always carry a read/write timeout."""
|
||||
|
||||
def __init__(self, *args, **kwargs):
|
||||
super().__init__(*args, **kwargs)
|
||||
self._inflight = {} # thread ident -> monotonic start time
|
||||
self._inflight_lock = threading.Lock()
|
||||
|
||||
# -- (1) client socket timeout ------------------------------------------
|
||||
def enqueue_req(self, conn):
|
||||
# Same three steps as ThreadWorker.enqueue_req, with the timeout set
|
||||
# right after conn.init() -- init() is what calls setblocking(True)
|
||||
# (== settimeout(None)), and it runs again on every keep-alive reuse,
|
||||
# so the timeout must be re-applied here each time, not at accept().
|
||||
conn.init()
|
||||
if CLIENT_TIMEOUT > 0:
|
||||
conn.sock.settimeout(CLIENT_TIMEOUT)
|
||||
fs = self.tpool.submit(self.handle, conn)
|
||||
self._wrap_future(fs, conn)
|
||||
|
||||
# -- busy tracking --------------------------------------------------------
|
||||
def handle(self, conn):
|
||||
ident = threading.get_ident()
|
||||
with self._inflight_lock:
|
||||
self._inflight[ident] = time.monotonic()
|
||||
try:
|
||||
return super().handle(conn)
|
||||
finally:
|
||||
with self._inflight_lock:
|
||||
self._inflight.pop(ident, None)
|
||||
|
||||
def pool_status(self):
|
||||
now = time.monotonic()
|
||||
with self._inflight_lock:
|
||||
starts = list(self._inflight.values())
|
||||
return {
|
||||
'pid': os.getpid(),
|
||||
'threads': self.cfg.threads,
|
||||
'busy': len(starts),
|
||||
'oldest_busy_seconds': round(now - min(starts), 1) if starts else 0.0,
|
||||
'client_timeout_seconds': CLIENT_TIMEOUT,
|
||||
}
|
||||
|
||||
# -- (2) watchdog ---------------------------------------------------------
|
||||
def _wedged_for(self):
|
||||
"""Seconds the pool has been completely wedged (every thread busy in
|
||||
its current request), measured from the YOUNGEST in-flight request.
|
||||
0 when at least one thread is free."""
|
||||
with self._inflight_lock:
|
||||
starts = list(self._inflight.values())
|
||||
if len(starts) < self.cfg.threads:
|
||||
return 0.0
|
||||
return time.monotonic() - max(starts)
|
||||
|
||||
def _dump_stacks(self):
|
||||
frames = sys._current_frames()
|
||||
names = {t.ident: t.name for t in threading.enumerate()}
|
||||
out = []
|
||||
for ident, frame in frames.items():
|
||||
out.append('--- thread %s (%s)\n%s' % (
|
||||
ident, names.get(ident, '?'), ''.join(traceback.format_stack(frame))))
|
||||
return '\n'.join(out)
|
||||
|
||||
def _watchdog(self):
|
||||
while self.alive:
|
||||
time.sleep(WATCHDOG_INTERVAL)
|
||||
wedged = self._wedged_for()
|
||||
if wedged > WEDGE_SECONDS:
|
||||
self.log.critical(
|
||||
'WEDGED WORKER (pid %s): all %s threads busy in the same request '
|
||||
'for %.0fs > HAPROXY_MGR_WEDGE_SECONDS=%s. Exiting so the master '
|
||||
'respawns it. Thread stacks:\n%s',
|
||||
os.getpid(), self.cfg.threads, wedged, WEDGE_SECONDS,
|
||||
self._dump_stacks())
|
||||
for h in logging.getLogger('gunicorn.error').handlers:
|
||||
try:
|
||||
h.flush()
|
||||
except Exception:
|
||||
pass
|
||||
# os._exit, not SIGTERM: a graceful exit joins the (stuck,
|
||||
# non-daemon) pool threads at interpreter shutdown and would
|
||||
# hang until the master's --timeout escalates to SIGKILL.
|
||||
os._exit(WEDGED_EXIT_CODE)
|
||||
|
||||
def init_process(self):
|
||||
global _current_worker
|
||||
_current_worker = self
|
||||
try:
|
||||
self.log.error_log.addFilter(_QuietClientTimeout())
|
||||
except AttributeError:
|
||||
pass
|
||||
if WEDGE_SECONDS > 0:
|
||||
threading.Thread(target=self._watchdog, name='wedge-watchdog',
|
||||
daemon=True).start()
|
||||
super().init_process() # runs the event loop; does not return
|
||||
+32
-2
@@ -51,6 +51,28 @@ def _bounded_subprocess_run(*args, **kwargs):
|
||||
|
||||
subprocess.run = _bounded_subprocess_run
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Default socket timeout (incident 2026-10-09) -- defence in depth only
|
||||
# ---------------------------------------------------------------------------
|
||||
# This module makes no outbound network calls today (ACME, HAProxy's admin
|
||||
# socket etc. all go through bounded subprocesses above). This default makes
|
||||
# sure any socket created in-process later -- a urllib/http.client call added
|
||||
# to some handler -- cannot block a worker thread forever by omission.
|
||||
#
|
||||
# It does NOT protect the API's CLIENT connections: gunicorn's gthread worker
|
||||
# calls sock.setblocking(True) on each one, which resets the timeout to None
|
||||
# and overrides this default. That is what actually wedged the pool on
|
||||
# 2026-10-09; it is fixed by haproxy_gunicorn_worker.TimeoutThreadWorker.
|
||||
DEFAULT_SOCKET_TIMEOUT = float(os.environ.get('HAPROXY_MGR_SOCKET_DEFAULT_TIMEOUT', '60'))
|
||||
if DEFAULT_SOCKET_TIMEOUT > 0:
|
||||
socket.setdefaulttimeout(DEFAULT_SOCKET_TIMEOUT)
|
||||
|
||||
try:
|
||||
from haproxy_gunicorn_worker import pool_status as _gunicorn_pool_status
|
||||
except Exception: # dev server / tests without gunicorn
|
||||
def _gunicorn_pool_status():
|
||||
return None
|
||||
|
||||
app = Flask(__name__)
|
||||
|
||||
# Default page server (port 8080) — served to HAProxy clients whose request hit
|
||||
@@ -741,11 +763,19 @@ def health_check():
|
||||
cursor.execute('SELECT 1')
|
||||
cursor.fetchone()
|
||||
|
||||
return jsonify({
|
||||
body = {
|
||||
'status': 'healthy',
|
||||
'haproxy_status': 'running' if haproxy_running else 'stopped',
|
||||
'database': 'connected'
|
||||
}), 200
|
||||
}
|
||||
# Pool saturation of the worker that answered ('busy' includes this
|
||||
# probe). Leaking threads show as busy/oldest_busy_seconds climbing;
|
||||
# a fully wedged worker cannot answer at all, which is what the
|
||||
# healthcheck's short --max-time catches.
|
||||
pool = _gunicorn_pool_status()
|
||||
if pool is not None:
|
||||
body['worker'] = pool
|
||||
return jsonify(body), 200
|
||||
except Exception as e:
|
||||
return jsonify({
|
||||
'status': 'unhealthy',
|
||||
|
||||
Executable
+31
@@ -0,0 +1,31 @@
|
||||
#!/usr/bin/env bash
|
||||
# Container liveness probe: BOTH planes must answer quickly.
|
||||
#
|
||||
# 1. Management API (:8000) -- GET /health with a short --max-time. On
|
||||
# 2026-10-09 (sdbees) the API workers' thread pools were wedged for long
|
||||
# enough that /health hung 40s+, while the container reported "healthy"
|
||||
# because the deployed --health-cmd only probed :80. A hung API is a dead
|
||||
# control plane (every WHP site update times out), so it must turn the
|
||||
# container unhealthy.
|
||||
# 2. HAProxy data plane (:80) -- any HTTP answer at all (the default page,
|
||||
# a redirect, a 4xx/5xx) proves HAProxy accepted and answered. Only a
|
||||
# connect/timeout failure fails it, which is why there is no -f here.
|
||||
#
|
||||
# 127.0.0.1, not localhost: the API binds IPv4 only, and resolving localhost
|
||||
# to ::1 first costs a failed connect on every probe.
|
||||
#
|
||||
# WHP's lib-edge-container.sh overrides the image HEALTHCHECK with its own
|
||||
# --health-cmd; point that at this script so the fleet gets the same probe.
|
||||
set -u
|
||||
API_TIMEOUT="${HAPROXY_MGR_HEALTH_API_TIMEOUT:-4}"
|
||||
EDGE_TIMEOUT="${HAPROXY_MGR_HEALTH_EDGE_TIMEOUT:-5}"
|
||||
|
||||
if ! curl -sf -o /dev/null --max-time "$API_TIMEOUT" http://127.0.0.1:8000/health; then
|
||||
echo "management API :8000 /health failed or took longer than ${API_TIMEOUT}s"
|
||||
exit 1
|
||||
fi
|
||||
if ! curl -s -o /dev/null --max-time "$EDGE_TIMEOUT" http://127.0.0.1/; then
|
||||
echo "HAProxy :80 did not answer within ${EDGE_TIMEOUT}s"
|
||||
exit 1
|
||||
fi
|
||||
exit 0
|
||||
+14
-3
@@ -77,7 +77,7 @@ HAPROXY_SUPERVISOR_INTERVAL="${HAPROXY_SUPERVISOR_INTERVAL:-15}"
|
||||
) &
|
||||
|
||||
# Phase 2: WSGI servers
|
||||
# Tunable via env: HAPROXY_MGR_API_WORKERS (default 1), HAPROXY_MGR_API_TIMEOUT
|
||||
# Tunable via env: HAPROXY_MGR_API_WORKERS (default 2), HAPROXY_MGR_API_TIMEOUT
|
||||
# (default 120 — API can do slow ACME calls), HAPROXY_MGR_MAX_REQUESTS (default
|
||||
# 1000 — worker recycle frequency).
|
||||
#
|
||||
@@ -91,12 +91,23 @@ API_TIMEOUT="${HAPROXY_MGR_API_TIMEOUT:-120}"
|
||||
MAX_REQ="${HAPROXY_MGR_MAX_REQUESTS:-1000}"
|
||||
MAX_REQ_JITTER="${HAPROXY_MGR_MAX_REQUESTS_JITTER:-100}"
|
||||
|
||||
# Worker class (incident 2026-10-09): stock gthread makes every client socket
|
||||
# fully blocking with NO timeout, so any peer that sends a few bytes and goes
|
||||
# quiet (TLS hello on this plain-HTTP port, scanners -- :8000 is published on
|
||||
# 0.0.0.0) pins a pool thread forever; 4 of them wedge a worker. This subclass
|
||||
# sets a per-connection socket timeout (HAPROXY_MGR_CLIENT_TIMEOUT, default
|
||||
# 20s) and runs a watchdog that exits a worker whose threads have ALL been
|
||||
# stuck for HAPROXY_MGR_WEDGE_SECONDS (default 1200) so the master respawns it.
|
||||
# See haproxy_gunicorn_worker.py. --timeout below does NOT cover either case:
|
||||
# for gthread it only watches the main thread's heartbeat.
|
||||
WORKER_CLASS="haproxy_gunicorn_worker.TimeoutThreadWorker"
|
||||
|
||||
# Default page server on :8080. Stays in the background.
|
||||
# --threads 4 lets one worker handle bursts of blocked-IP/default-page hits
|
||||
# without forking. --max-requests recycles the worker to bound memory drift.
|
||||
gunicorn \
|
||||
--bind 0.0.0.0:8080 \
|
||||
--workers 1 --threads 4 --worker-class gthread \
|
||||
--workers 1 --threads 4 --worker-class "${WORKER_CLASS}" \
|
||||
--max-requests "${MAX_REQ}" --max-requests-jitter "${MAX_REQ_JITTER}" \
|
||||
--timeout 30 \
|
||||
--access-logfile - --error-logfile - --log-level info \
|
||||
@@ -108,7 +119,7 @@ gunicorn \
|
||||
# up). Longer --timeout because cert issuance hits ACME and can take a while.
|
||||
exec gunicorn \
|
||||
--bind 0.0.0.0:8000 \
|
||||
--workers "${API_WORKERS}" --threads 4 --worker-class gthread \
|
||||
--workers "${API_WORKERS}" --threads 4 --worker-class "${WORKER_CLASS}" \
|
||||
--max-requests "${MAX_REQ}" --max-requests-jitter "${MAX_REQ_JITTER}" \
|
||||
--timeout "${API_TIMEOUT}" \
|
||||
--access-logfile - --error-logfile - --log-level info \
|
||||
|
||||
@@ -0,0 +1,356 @@
|
||||
#!/usr/bin/env python3
|
||||
"""Regression tests: a silent peer must not be able to wedge the API's threads.
|
||||
|
||||
Why this file exists
|
||||
--------------------
|
||||
On 2026-10-09 (sdbees) both :8000 API workers had 7 of 8 gthread pool threads
|
||||
blocked in the kernel in tcp_recvmsg -> sk_wait_data, /health hung 40s+, and the
|
||||
container stayed "healthy". The app makes no in-process outbound socket reads;
|
||||
the blocked reads were gunicorn gthread reading the CLIENT socket, which it
|
||||
makes fully blocking with no timeout (TConn.init -> setblocking(True)).
|
||||
|
||||
These tests run REAL gunicorn processes (no mocks) against tiny WSGI apps and
|
||||
pin:
|
||||
|
||||
* the failure mode itself, on the stock gthread worker (control);
|
||||
* that haproxy_gunicorn_worker.TimeoutThreadWorker frees the thread when a
|
||||
client stalls before / during the request line, mid-body, or on a reused
|
||||
keep-alive connection;
|
||||
* that a legitimately SLOW request (handling time > client timeout) is not
|
||||
cut off -- the timeout bounds socket I/O, not request duration;
|
||||
* the watchdog: a worker whose every thread is stuck is replaced;
|
||||
* the timeout is logged as one line, not a traceback per scanner;
|
||||
* haproxy_manager's socket.setdefaulttimeout: an in-process client call to a
|
||||
stalled upstream (accepts, never replies) times out instead of hanging;
|
||||
* why that default alone is not enough (setblocking(True) clears it).
|
||||
|
||||
Running
|
||||
-------
|
||||
python3 scripts/test-gunicorn-socket-timeouts.py
|
||||
|
||||
stdlib unittest, like the other scripts/test-*.py; needs only the app's own
|
||||
requirements (gunicorn, Flask...). Runs in the Docker build gate. ~25s.
|
||||
"""
|
||||
|
||||
import os
|
||||
import socket
|
||||
import subprocess
|
||||
import sys
|
||||
import tempfile
|
||||
import textwrap
|
||||
import threading
|
||||
import time
|
||||
import unittest
|
||||
import urllib.request
|
||||
|
||||
REPO_DIR = os.path.abspath(
|
||||
os.environ.get('HAPROXY_MANAGER_DIR',
|
||||
os.path.join(os.path.dirname(os.path.abspath(__file__)), '..')))
|
||||
|
||||
try:
|
||||
import gunicorn # noqa: F401
|
||||
except ImportError:
|
||||
sys.stderr.write('SKIP: gunicorn not installed (pip install -r requirements.txt)\n')
|
||||
raise SystemExit(77)
|
||||
|
||||
WSGI_APP = textwrap.dedent('''\
|
||||
import os, time
|
||||
|
||||
def app(environ, start_response):
|
||||
path = environ.get('PATH_INFO', '/')
|
||||
if path == '/sleep':
|
||||
time.sleep(float(environ.get('QUERY_STRING') or 3))
|
||||
elif path == '/hang':
|
||||
time.sleep(3600)
|
||||
elif path == '/body':
|
||||
n = int(environ.get('CONTENT_LENGTH') or 0)
|
||||
environ['wsgi.input'].read(n)
|
||||
body = ('pid=%d' % os.getpid()).encode()
|
||||
start_response('200 OK', [('Content-Type', 'text/plain'),
|
||||
('Content-Length', str(len(body)))])
|
||||
return [body]
|
||||
''')
|
||||
|
||||
|
||||
def free_port():
|
||||
s = socket.socket()
|
||||
s.bind(('127.0.0.1', 0))
|
||||
port = s.getsockname()[1]
|
||||
s.close()
|
||||
return port
|
||||
|
||||
|
||||
def http_get(port, path='/', timeout=5):
|
||||
with urllib.request.urlopen('http://127.0.0.1:%d%s' % (port, path),
|
||||
timeout=timeout) as r:
|
||||
return r.read().decode()
|
||||
|
||||
|
||||
class Gunicorn:
|
||||
"""A real gunicorn master on a free port, with its output captured."""
|
||||
|
||||
def __init__(self, worker_class, threads=1, env=None):
|
||||
self.tmp = tempfile.mkdtemp(prefix='gunicorn-timeout-test-')
|
||||
with open(os.path.join(self.tmp, 'tapp.py'), 'w') as fh:
|
||||
fh.write(WSGI_APP)
|
||||
self.port = free_port()
|
||||
self.log_path = os.path.join(self.tmp, 'gunicorn.log')
|
||||
e = dict(os.environ)
|
||||
e.update(env or {})
|
||||
self.log = open(self.log_path, 'w')
|
||||
self.proc = subprocess.Popen(
|
||||
[sys.executable, '-m', 'gunicorn',
|
||||
'--bind', '127.0.0.1:%d' % self.port,
|
||||
'--workers', '1', '--threads', str(threads),
|
||||
'--worker-class', worker_class,
|
||||
'--timeout', '120', '--graceful-timeout', '2',
|
||||
'--log-level', 'info', '--error-logfile', '-',
|
||||
'--pythonpath', '%s,%s' % (REPO_DIR, self.tmp),
|
||||
'tapp:app'],
|
||||
stdout=self.log, stderr=subprocess.STDOUT, env=e)
|
||||
deadline = time.time() + 15
|
||||
while time.time() < deadline:
|
||||
try:
|
||||
http_get(self.port, '/', timeout=1)
|
||||
return
|
||||
except Exception:
|
||||
time.sleep(0.2)
|
||||
self.stop()
|
||||
raise RuntimeError('gunicorn did not come up:\n' + self.output())
|
||||
|
||||
def output(self):
|
||||
self.log.flush()
|
||||
with open(self.log_path) as fh:
|
||||
return fh.read()
|
||||
|
||||
def stop(self):
|
||||
if self.proc.poll() is None:
|
||||
self.proc.terminate()
|
||||
try:
|
||||
self.proc.wait(5)
|
||||
except subprocess.TimeoutExpired:
|
||||
self.proc.kill()
|
||||
self.proc.wait()
|
||||
self.log.close()
|
||||
|
||||
|
||||
def stall_client(port, payload=b'\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03'):
|
||||
"""Connect and send a few bytes that are not a complete HTTP request (by
|
||||
default the start of a TLS ClientHello -- what an HTTPS scanner sends to
|
||||
this plain-HTTP port), then go silent and keep the connection open."""
|
||||
s = socket.create_connection(('127.0.0.1', port))
|
||||
if payload:
|
||||
s.sendall(payload)
|
||||
return s
|
||||
|
||||
|
||||
def wait_closed_by_server(sock, within):
|
||||
"""True if the server closed (EOF/RST) the connection within `within` s."""
|
||||
sock.settimeout(within)
|
||||
try:
|
||||
while True:
|
||||
data = sock.recv(4096)
|
||||
if not data:
|
||||
return True
|
||||
except (ConnectionResetError, BrokenPipeError):
|
||||
return True
|
||||
except socket.timeout:
|
||||
return False
|
||||
|
||||
|
||||
STOCK = 'gthread'
|
||||
FIXED = 'haproxy_gunicorn_worker.TimeoutThreadWorker'
|
||||
FAST = {'HAPROXY_MGR_CLIENT_TIMEOUT': '1'}
|
||||
|
||||
|
||||
class StockGthreadControl(unittest.TestCase):
|
||||
"""Proves the failure mode is real, so the fixed-worker tests mean something."""
|
||||
|
||||
def test_stock_gthread_is_wedged_by_one_silent_client(self):
|
||||
g = Gunicorn(STOCK, threads=1)
|
||||
self.addCleanup(g.stop)
|
||||
s = stall_client(g.port)
|
||||
self.addCleanup(s.close)
|
||||
time.sleep(0.3)
|
||||
with self.assertRaises(Exception, msg='stock gthread should be wedged'):
|
||||
http_get(g.port, '/', timeout=3)
|
||||
|
||||
|
||||
class TimeoutWorkerTests(unittest.TestCase):
|
||||
|
||||
def start(self, threads=1, env=None):
|
||||
g = Gunicorn(FIXED, threads=threads, env=env or FAST)
|
||||
self.addCleanup(g.stop)
|
||||
return g
|
||||
|
||||
def test_silent_client_is_dropped_and_thread_freed(self):
|
||||
g = self.start()
|
||||
s = stall_client(g.port)
|
||||
self.addCleanup(s.close)
|
||||
t0 = time.time()
|
||||
# Only one thread: this request can only be served once the stalled
|
||||
# connection has released it.
|
||||
self.assertTrue(http_get(g.port, '/', timeout=5).startswith('pid='))
|
||||
self.assertLess(time.time() - t0, 4)
|
||||
self.assertTrue(wait_closed_by_server(s, 3),
|
||||
'server should have closed the stalled connection')
|
||||
|
||||
def test_connect_and_send_nothing_does_not_hold_a_thread(self):
|
||||
# Never readable -> never handed to a pool thread (main loop only).
|
||||
g = self.start()
|
||||
s = stall_client(g.port, payload=b'')
|
||||
self.addCleanup(s.close)
|
||||
self.assertTrue(http_get(g.port, '/', timeout=3).startswith('pid='))
|
||||
|
||||
def test_half_written_headers(self):
|
||||
g = self.start()
|
||||
s = stall_client(g.port, payload=b'GET /health HTTP/1.1\r\nHost: x\r\n')
|
||||
self.addCleanup(s.close)
|
||||
self.assertTrue(http_get(g.port, '/', timeout=5).startswith('pid='))
|
||||
self.assertTrue(wait_closed_by_server(s, 3))
|
||||
|
||||
def test_body_shorter_than_content_length(self):
|
||||
g = self.start()
|
||||
s = stall_client(g.port, payload=(
|
||||
b'POST /body HTTP/1.1\r\nHost: x\r\nContent-Length: 100\r\n\r\n0123456789'))
|
||||
self.addCleanup(s.close)
|
||||
self.assertTrue(http_get(g.port, '/', timeout=5).startswith('pid='))
|
||||
|
||||
def test_timeout_reapplied_on_keepalive_reuse(self):
|
||||
g = self.start()
|
||||
s = socket.create_connection(('127.0.0.1', g.port))
|
||||
self.addCleanup(s.close)
|
||||
s.sendall(b'GET / HTTP/1.1\r\nHost: x\r\n\r\n')
|
||||
s.settimeout(3)
|
||||
self.assertIn(b'200 OK', s.recv(4096))
|
||||
# Same connection, now stall mid-request. gthread calls conn.init()
|
||||
# (setblocking(True)) again for the reused connection.
|
||||
s.sendall(b'GET / HTT')
|
||||
time.sleep(0.3)
|
||||
self.assertTrue(http_get(g.port, '/', timeout=5).startswith('pid='))
|
||||
self.assertTrue(wait_closed_by_server(s, 3))
|
||||
|
||||
def test_slow_legit_request_is_not_cut_off(self):
|
||||
# Handling takes 2.5s, client timeout is 1s: must still succeed.
|
||||
g = self.start()
|
||||
self.assertTrue(http_get(g.port, '/sleep?2.5', timeout=10).startswith('pid='))
|
||||
|
||||
def test_timeout_logged_as_one_line_not_traceback(self):
|
||||
g = self.start()
|
||||
s = stall_client(g.port)
|
||||
self.addCleanup(s.close)
|
||||
http_get(g.port, '/', timeout=5)
|
||||
time.sleep(0.3)
|
||||
out = g.output()
|
||||
self.assertIn('Closed client connection idle', out)
|
||||
self.assertNotIn('Traceback', out)
|
||||
|
||||
def test_watchdog_replaces_fully_wedged_worker(self):
|
||||
g = self.start(env={'HAPROXY_MGR_CLIENT_TIMEOUT': '1',
|
||||
'HAPROXY_MGR_WEDGE_SECONDS': '2',
|
||||
'HAPROXY_MGR_WATCHDOG_INTERVAL': '0.5'})
|
||||
pid_before = http_get(g.port, '/')
|
||||
# Wedge the only thread inside the app (not a socket read).
|
||||
hung = threading.Thread(target=lambda: self._swallow(g.port), daemon=True)
|
||||
hung.start()
|
||||
time.sleep(0.5)
|
||||
deadline = time.time() + 12
|
||||
pid_after = None
|
||||
while time.time() < deadline:
|
||||
try:
|
||||
pid_after = http_get(g.port, '/', timeout=2)
|
||||
if pid_after != pid_before:
|
||||
break
|
||||
except Exception:
|
||||
pass
|
||||
time.sleep(0.3)
|
||||
self.assertIsNotNone(pid_after)
|
||||
self.assertNotEqual(pid_before, pid_after, 'worker was not replaced')
|
||||
out = g.output()
|
||||
self.assertIn('WEDGED WORKER', out)
|
||||
self.assertIn('tapp.py', out) # the stuck thread's stack was dumped
|
||||
self.assertIsNone(g.proc.poll(), 'master must keep running')
|
||||
|
||||
def test_watchdog_leaves_partially_busy_pool_alone(self):
|
||||
# 2 threads, one hung forever: the pool still serves, so no restart.
|
||||
g = self.start(threads=2, env={'HAPROXY_MGR_CLIENT_TIMEOUT': '1',
|
||||
'HAPROXY_MGR_WEDGE_SECONDS': '1',
|
||||
'HAPROXY_MGR_WATCHDOG_INTERVAL': '0.3'})
|
||||
pid_before = http_get(g.port, '/')
|
||||
threading.Thread(target=lambda: self._swallow(g.port), daemon=True).start()
|
||||
time.sleep(3)
|
||||
self.assertEqual(pid_before, http_get(g.port, '/', timeout=3))
|
||||
self.assertNotIn('WEDGED WORKER', g.output())
|
||||
|
||||
@staticmethod
|
||||
def _swallow(port):
|
||||
try:
|
||||
http_get(port, '/hang', timeout=60)
|
||||
except Exception:
|
||||
pass
|
||||
|
||||
|
||||
class StalledUpstreamDefaultTimeout(unittest.TestCase):
|
||||
"""haproxy_manager sets socket.setdefaulttimeout() at import. An in-process
|
||||
client call to an upstream that accepts and never replies must time out."""
|
||||
|
||||
def test_in_process_client_to_stalled_upstream_times_out(self):
|
||||
srv = socket.socket()
|
||||
srv.bind(('127.0.0.1', 0))
|
||||
srv.listen(5)
|
||||
self.addCleanup(srv.close)
|
||||
port = srv.getsockname()[1]
|
||||
accepted = []
|
||||
threading.Thread(target=lambda: accepted.append(srv.accept()),
|
||||
daemon=True).start()
|
||||
# Import the real module in a child (it changes process-global socket
|
||||
# state and opens its log files at import), then make a client call
|
||||
# with NO explicit timeout -- what a careless future handler would do.
|
||||
probe = textwrap.dedent('''\
|
||||
import logging, os, sys, tempfile, time, urllib.request
|
||||
d = tempfile.mkdtemp()
|
||||
real = logging.FileHandler
|
||||
logging.FileHandler = lambda fn, *a, **k: real(os.path.join(d, os.path.basename(fn)), *a, **k)
|
||||
os.chdir(sys.argv[1]); sys.path.insert(0, sys.argv[1])
|
||||
import haproxy_manager
|
||||
logging.FileHandler = real
|
||||
import socket
|
||||
print('default', socket.getdefaulttimeout())
|
||||
t0 = time.time()
|
||||
try:
|
||||
urllib.request.urlopen('http://127.0.0.1:%s/' % sys.argv[2]).read()
|
||||
print('result returned')
|
||||
except Exception as e:
|
||||
print('result', type(e).__name__, round(time.time() - t0, 1))
|
||||
''')
|
||||
env = dict(os.environ, HAPROXY_MGR_SOCKET_DEFAULT_TIMEOUT='1.5')
|
||||
r = subprocess.run([sys.executable, '-c', probe, REPO_DIR, str(port)],
|
||||
capture_output=True, text=True, timeout=30, env=env)
|
||||
if 'No module named' in r.stderr and 'flask' in r.stderr.lower():
|
||||
self.skipTest('Flask not installed')
|
||||
self.assertIn('default 1.5', r.stdout, r.stderr)
|
||||
line = [l for l in r.stdout.splitlines() if l.startswith('result')][0]
|
||||
self.assertTrue(line.startswith('result TimeoutError '), line)
|
||||
elapsed = float(line.split()[-1])
|
||||
self.assertLess(elapsed, 5)
|
||||
self.assertTrue(accepted, 'upstream never saw the connection')
|
||||
accepted[0][0].close()
|
||||
|
||||
def test_default_timeout_alone_does_not_cover_gthread_client_sockets(self):
|
||||
# Documents why the custom worker exists: gthread's setblocking(True)
|
||||
# resets any timeout -- including the process default -- to None.
|
||||
old = socket.getdefaulttimeout()
|
||||
socket.setdefaulttimeout(60)
|
||||
try:
|
||||
a, b = socket.socketpair()
|
||||
finally:
|
||||
socket.setdefaulttimeout(old)
|
||||
self.addCleanup(a.close)
|
||||
self.addCleanup(b.close)
|
||||
self.assertEqual(a.gettimeout(), 60)
|
||||
a.setblocking(True)
|
||||
self.assertIsNone(a.gettimeout())
|
||||
|
||||
|
||||
if __name__ == '__main__':
|
||||
unittest.main(verbosity=2)
|
||||
Reference in new issue
Block a user