feast serve: Gunicorn worker deadlocks on startup when forked during a /metrics request (follow-up to #6647) #6928

Expected behavior

With metrics enabled, Gunicorn replaces a worker after --max-requests requests and the new worker
starts serving.

Current behavior

Occasionally the new worker never starts. The log ends with Worker exiting (pid: N) and there is no
Booting worker with pid: ... after it. The worker process exists but is blocked forever; the master
keeps the listening socket open and the metrics server (a thread in the master) keeps answering
/metrics, so TCP health checks still pass while no request is served. Gunicorn's worker timeout does
not kill it either (separate Gunicorn issue: a worker that hangs before its first notify() is never
timed out).

In our production (2 deployments, 26 pods, ~17,500 worker recycles per day) this happened 14 times
in 7 days; each pod served nothing for ~1 h until its listen backlog filled up and Kubernetes' TCP
liveness probe failed.

Root cause

Same class of bug as #6647 (fixed for the freshness thread in #6648): a thread started in the
Gunicorn master before fork().

feature_server.start_server() calls feast_metrics.start_metrics_server() in the Gunicorn master,
before FeastServeApplication(...).run() forks the workers. That starts the metrics HTTP server
(wsgiref make_server(...), now _make_metrics_httpd) as a daemon thread with the default
WSGIRequestHandler, which writes an access-log line to sys.stderr for every request
(log_message).

While that thread is inside sys.stderr.write, it holds the internal lock of stderr's
BufferedWriter. If Gunicorn forks a worker at that moment, the child inherits the lock in the locked
state, and the thread that would release it does not exist in the child. The child's first action is
self.log.info("Booting worker with pid: %s", ...) (gunicorn/arbiter.py, spawn_worker), which
writes to stderr and blocks forever. Python's logging module re-initialises its own handler locks
after fork; the BufferedWriter lock is not re-initialised.

Python warns about exactly this when feast serve starts:

gunicorn/arbiter.py:666: DeprecationWarning: This process (pid=16635) is multi-threaded, use of fork() may lead to deadlocks in the child.
  pid = os.fork()

Evidence

• Python stack of a stuck worker (Linux, faulthandler dump), identical in all 10 hangs we captured:

  File "/usr/local/lib/python3.12/logging/__init__.py", line 1163 in emit      # stream.write(...)
  File "/usr/local/lib/python3.12/logging/__init__.py", line 1028 in handle
  ...
  File ".../gunicorn/glogging.py", line 277 in info
  File ".../gunicorn/arbiter.py", line 680 in spawn_worker                      # "Booting worker"
  File ".../gunicorn/arbiter.py", line 719 in spawn_workers
  File ".../gunicorn/arbiter.py", line 634 in manage_workers
  File ".../gunicorn/arbiter.py", line 228 in run
  File ".../feast/feature_server.py", line 941 in start_server
  

  The stuck worker has 1 thread, waiting on a futex; the master has 2 threads (main + metrics server).
• Native stack of a stuck worker (macOS sample, 879 of 879 samples):

  _io_TextIOWrapper_write → _textiowrapper_writeflush → _io_BufferedWriter_write
    → _enter_buffered_busy → PyThread_acquire_lock_timed → __psynch_cvwait
  

• Production: in 12 of 12 hangs, a /metrics scrape was logged 0–1 s after the last Worker exiting;
  for normal recycles that happens 9.3% of the time (39 of 420).
• Controlled test (Kubernetes, --max-requests 20, 4 back-to-back /metrics scrapers, a fresh pod
  every 100 forks): 5 hangs in 318 forks without a change; 0 hangs in 2,000 forks when only the
  access log of the metrics server is silenced (the change proposed in the PR). Locally (macOS, steps
  below): a hang after 12–29 forks without the change, 0 in 336 forks with it.

Steps to reproduce

Feast 0.65.0 or master, no external services:

feast init -m demo && cd demo/feature_repo
cat > feature_store.yaml <<'EOF'
project: demo
registry: data/registry.db
provider: local
online_store:
    type: sqlite
    path: data/online_store.db
entity_key_serialization_version: 3
feature_server:
    metrics:
        enabled: true
        freshness: false   # only the metrics server thread (freshness was #6647)
EOF
mkdir -p data && feast apply

# terminal 1: recycle the worker every 20 requests
feast serve --max-requests 20 --max-requests-jitter 0 2>&1 | tee serve.log

# terminal 2: keep the metrics thread busy + send requests
for i in 1 2 3 4; do (while true; do curl -s -o /dev/null http://127.0.0.1:8000/metrics; done) & done
while true; do curl -s -o /dev/null -m 2 http://127.0.0.1:6566/health; done

Within seconds to a few minutes, serve.log stops at Worker exiting (pid: N) with no
Booting worker after it, and /health stops answering. py-spy dump --pid <child> (or sample
on macOS) shows the child blocked in the stderr write.

Possible solution

1. Minimal: give the metrics server a request handler that does not log
   (make_server(..., handler_class=...) with a no-op log_message), as prometheus_client's own
   start_http_server does (_SilentHandler). PR to follow. This removes the stderr write we observed.
2. More complete: do not run any thread in the Gunicorn master while it forks, e.g. serve the
   multiprocess metrics from a separate process. Any other lock taken by the metrics thread could
   cause the same deadlock in the future.

Environment

Feast 0.65.0 (also checked 0.66.0 and master @ bc5aeef), gunicorn 25.0.3, uvicorn-worker 0.3.0,
Python 3.12, python:3.12-slim on Linux arm64 (EKS) and macOS.