From 983f455bba9a84ee5d568fd223e5430ecdcf12d4 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 11:41:57 +0700 Subject: [PATCH 1/7] fix: share uvicorn log handler and drop blocking multilog pipes --- integrations/perception-service/Makefile | 19 +++-- .../perception-service/docs/deployment.md | 18 +++-- .../docs/troubleshooting.md | 65 ++++++++++------ .../scripts/run-with-restart.sh | 78 +++++++++++++++++-- .../perception-service/src/dlserver/app.py | 21 +++-- .../perception-service/src/lbserver/app.py | 20 +++-- 6 files changed, 155 insertions(+), 66 deletions(-) diff --git a/integrations/perception-service/Makefile b/integrations/perception-service/Makefile index 4046acc16..60e33815a 100644 --- a/integrations/perception-service/Makefile +++ b/integrations/perception-service/Makefile @@ -122,15 +122,19 @@ start-runpod-master: start-nginx start-runpod-dlserver start-runpod-lbserver start-runpod-master-ssl: start-nginx-ssl start-runpod-dlserver start-runpod-lbserver start-runpod-slave: start-nginx stop-runpod-dlserver install - @command -v multilog >/dev/null || apt-get install -y daemontools - @mkdir -p /workspace/logs/dlserver/stderr - @$(SET_TRT_LD_PATH); nohup python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver --pid-file $(DLSERVER_PID) &1 | multilog t s1048576 n3 /workspace/logs/dlserver/stderr & + @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ + --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ + --log-dir /workspace/logs/dlserver -- \ + python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver \ + /dev/null 2>&1 & @echo "dlserver started on port $(LBSERVER_PORT) (slave, no LB)" start-runpod-slave-ssl: start-nginx-ssl stop-runpod-dlserver install - @command -v multilog >/dev/null || apt-get install -y daemontools - @mkdir -p /workspace/logs/dlserver/stderr - @$(SET_TRT_LD_PATH); nohup python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver --pid-file $(DLSERVER_PID) &1 | multilog t s1048576 n3 /workspace/logs/dlserver/stderr & + @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ + --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ + --log-dir /workspace/logs/dlserver -- \ + python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver \ + /dev/null 2>&1 & @echo "dlserver started on port $(LBSERVER_PORT) (slave-ssl, no LB)" gen-ssl-cert: @@ -172,7 +176,6 @@ start-nginx-ssl: gen-ssl-cert stop-nginx nginx -c /etc/nginx/perception-service-nginx-ssl.conf start-runpod-dlserver: install stop-runpod-dlserver - @command -v multilog >/dev/null || apt-get install -y daemontools @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ --log-dir /workspace/logs/dlserver -- \ @@ -194,7 +197,6 @@ stop-runpod-dlserver: @echo "dlserver stopped" start-runpod-lbserver: install-lb stop-runpod-lbserver - @command -v multilog >/dev/null || apt-get install -y daemontools @nohup bash scripts/run-with-restart.sh \ --pid-file $(LBSERVER_PID) --wrapper-pid-file $(LBSERVER_WRAPPER_PID) --cooldown 5 \ --log-dir /workspace/logs/lbserver -- \ @@ -219,6 +221,7 @@ start-jupyter: @if ! command -v jupyter-lab > /dev/null 2>&1; then \ python -m pip install jupyter; \ fi + @command -v multilog >/dev/null || apt-get install -y daemontools @mkdir -p /workspace/logs/jupyter @(sleep 3 && TOKEN=$$(grep -oP 'token=\K[a-f0-9]+' /workspace/logs/jupyter/current 2>/dev/null | tail -1); \ if [ -n "$$TOKEN" ]; then \ diff --git a/integrations/perception-service/docs/deployment.md b/integrations/perception-service/docs/deployment.md index 3801817da..6d10c2a89 100644 --- a/integrations/perception-service/docs/deployment.md +++ b/integrations/perception-service/docs/deployment.md @@ -98,6 +98,10 @@ make start-runpod-slave # nginx :8899 → dlserver :7999 (no LB on this make start-runpod-slave-ssl # same, HTTPS ``` +Slave nodes run under the same `run-with-restart.sh` watchdog as the master, so +they auto-restart on exit and get the same log rotation and size cap. `make +stop-runpod-dlserver` stops a slave node too. + On the **master**, point the LB at the local dlserver plus every slave's public endpoint, then start the master stack: @@ -133,7 +137,7 @@ Override with `DLSERVER_PORT`, `LBSERVER_PORT`, `JUPYTER_PORT` make variables. | `make start-lbserver` | Foreground lbserver on `:7999` | | `make start-runpod-master` | Background: nginx + dlserver + lbserver (HTTP) | | `make start-runpod-master-ssl` | Same with self-signed TLS | -| `make start-runpod-slave` | Background: nginx + dlserver only (no LB) | +| `make start-runpod-slave` | Background: nginx + dlserver only (no LB), with auto-restart watchdog | | `make start-runpod-slave-ssl` | Same with TLS | | `make start-runpod-dlserver` | Background dlserver with auto-restart watchdog | | `make start-runpod-lbserver` | Background lbserver with auto-restart watchdog | @@ -179,10 +183,14 @@ run-with-restart.sh [OPTIONS] -- COMMAND [ARGS...] --pid-file PATH inner process PID (for stop targets) --wrapper-pid-file PATH watchdog's own PID --cooldown SECONDS wait between restarts (default: 5) - --log-dir PATH structured logging via multilog: - log-dir/stdout/ server stdout - log-dir/stderr/ server stderr - log-dir/watchdog/ restart events + --log-dir PATH plain-file logging (never a pipe -- a blocked pipe + can freeze the server): + log-dir/stdout.log server stdout + log-dir/stderr.log server stderr + log-dir/watchdog.log restart events + Rotated to .1/.2/.3 at startup and whenever a file + exceeds MAX_LOG_BYTES (default 8 MiB, checked every + GUARD_INTERVAL seconds, default 60). ``` Sending `SIGTERM` to the wrapper gracefully stops the inner process and exits. diff --git a/integrations/perception-service/docs/troubleshooting.md b/integrations/perception-service/docs/troubleshooting.md index 317a36e55..cdcb32de5 100644 --- a/integrations/perception-service/docs/troubleshooting.md +++ b/integrations/perception-service/docs/troubleshooting.md @@ -55,30 +55,44 @@ are actually loaded, which is why the autostart probe checks for it. ## 2. Reading the logs -Logs are [multilog](https://cr.yp.to/daemontools/multilog.html) directories, not -files. The live file is always `current`, and every line is prefixed with a -TAI64N timestamp that must be decoded: +Logs are plain text files. No decoding is needed: ```bash -tail -100 /workspace/logs/dlserver/watchdog/current | tai64nlocal -tail -200 /workspace/logs/dlserver/stderr/current | tai64nlocal -tail -100 /workspace/logs/lbserver/watchdog/current | tai64nlocal -tail -50 /workspace/logs/autostart/autostart.log # plain text, no decoding +tail -100 /workspace/logs/dlserver/watchdog.log +tail -200 /workspace/logs/dlserver/stderr.log +tail -100 /workspace/logs/lbserver/watchdog.log +tail -50 /workspace/logs/autostart/autostart.log ``` -Without `tai64nlocal` every line starts with `@400000006a5db23a…` and you cannot -correlate anything with wall-clock time. - -Rotated segments live in the same directory, and **the suffix tells you how the -previous run ended**: - -| Suffix | Meaning | -|--------|---------| -| `@…​.s` | Normal rotation (hit the 1 MB size limit). Says nothing about health | -| `@…​.u` | multilog was killed before it could finalise the file — **abrupt termination of the whole process group** | - -A `.u` file's mtime is the last moment anything was written, which is your best -estimate of when the process died. +| File | Contents | +|------|----------| +| `/stdout.log` | server stdout | +| `/stderr.log` | server stderr (library warnings, tracebacks) | +| `/watchdog.log` | restart events from `run-with-restart.sh` | +| `/.log` | application log (`RotatingFileHandler`, 1 MB × 3) | +| `/uvicorn.log` | uvicorn error **and** access log (one shared handler) | + +Rotation keeps 3 generations as `.1`, `.2`, `.3`: + +- `stdout/stderr/watchdog.log` are rotated by `run-with-restart.sh` — once at + startup, and whenever a file exceeds `MAX_LOG_BYTES` (default 8 MiB, checked + every `GUARD_INTERVAL` seconds, default 60). The size guard **copies then + truncates in place**; it must never rename, because the server holds an + `O_APPEND` fd and would keep writing to the renamed inode. +- `.log` and `uvicorn.log` are rotated by Python's `RotatingFileHandler`. + +> **Historical note.** Before 2026-08-18 these were +> [multilog](https://cr.yp.to/daemontools/multilog.html) *directories* (`stdout/`, +> `stderr/`, `watchdog/`) whose live file was `current`, TAI64N-prefixed and read +> via `tai64nlocal`. Those directories may still exist with old data — decode them +> with `tai64nlocal` as before. They are no longer written to. +> +> multilog was removed because its documented reaction to a write error is to +> *pause and retry forever*, which stops it draining its input pipe. The server on +> the other end then blocks in `pipe_write` with no timeout and no way to run signal +> handlers — and that writer is the asyncio event loop. This froze lbserver on +> 2026-08-10 and dlserver on 2026-08-17. A plain file redirect cannot block the +> writer: a failed write returns an error instead. ## 3. Crash, or group kill? @@ -216,9 +230,14 @@ make start-runpod-master make info ``` -Always stop before starting. The stop targets also clear the stale -`/workspace/logs/*/stderr/lock` files that would otherwise block multilog on the -next start. +Always stop before starting. + +> The stop targets still `rm -f /workspace/logs/*/stderr/lock`. That is now a +> no-op left over from multilog and will be removed — the lock files are not +> recreated. Note the stop targets only kill the PIDs recorded in `/tmp/*.pid`, +> so multilogs or other tree members started by an older build can survive as +> orphans; check with +> `ps -eo pid,ppid,args | grep -aE 'multilog|run-with-restart'` before starting. Two things that silently produce a *misconfigured* server rather than a failure: diff --git a/integrations/perception-service/scripts/run-with-restart.sh b/integrations/perception-service/scripts/run-with-restart.sh index b2b9d0b52..78927389b 100755 --- a/integrations/perception-service/scripts/run-with-restart.sh +++ b/integrations/perception-service/scripts/run-with-restart.sh @@ -5,8 +5,11 @@ # --pid-file PATH: the inner process PID is written here on each start. # --wrapper-pid-file PATH: this wrapper's own PID is written here once at startup. # --cooldown SECONDS: wait between restarts (default: 5). -# --log-dir PATH: if set, stdout → log-dir/stdout/ and stderr → log-dir/stderr/ -# via multilog. Watchdog messages go to log-dir/watchdog/. +# --log-dir PATH: if set, stdout → log-dir/stdout.log, stderr → log-dir/stderr.log +# and watchdog messages → log-dir/watchdog.log. +# Plain files on purpose: a pipe to multilog can block the +# writer forever if multilog pauses on a write error, which +# wedges a single-threaded asyncio server (see MAX_LOG_BYTES). # # Sending SIGTERM to the wrapper gracefully stops the inner process and exits. @@ -36,18 +39,77 @@ fi # Write wrapper PID so the stop target can kill us [[ -n "$WRAPPER_PID_FILE" ]] && echo "$$" > "$WRAPPER_PID_FILE" +# Largest a log file may reach before the size guard copy-truncates it. +MAX_LOG_BYTES=${MAX_LOG_BYTES:-8388608} # 8 MiB +LOG_BACKUPS=3 +GUARD_INTERVAL=${GUARD_INTERVAL:-60} # seconds between size checks + +# Rename FILE aside on startup, keeping LOG_BACKUPS generations. Safe here because +# no process holds these files open yet. +rotate_on_start() { + local f=$1 i + [[ -f "$f" ]] || return 0 + rm -f "$f.$LOG_BACKUPS" + for ((i = LOG_BACKUPS - 1; i >= 1; i--)); do + [[ -f "$f.$i" ]] && mv -f "$f.$i" "$f.$((i + 1))" + done + mv -f "$f" "$f.1" +} + +# Cap a live log file. MUST copy-then-truncate, never rename: the child holds an +# O_APPEND fd, so renaming would leave it writing to the renamed inode forever +# (the deleted-but-open pattern that caused the 2026-08-10/17 freezes). +guard_size() { + local f=$1 i + [[ -f "$f" ]] || return 0 + local sz + sz=$(wc -c <"$f" 2>/dev/null || echo 0) + (( sz < MAX_LOG_BYTES )) && return 0 + rm -f "$f.$LOG_BACKUPS" + for ((i = LOG_BACKUPS - 1; i >= 1; i--)); do + [[ -f "$f.$i" ]] && mv -f "$f.$i" "$f.$((i + 1))" + done + cp -f "$f" "$f.1" && : >"$f" +} + # Set up logging if [[ -n "$LOG_DIR" ]]; then - mkdir -p "$LOG_DIR/stdout" "$LOG_DIR/stderr" "$LOG_DIR/watchdog" - # Redirect watchdog's own output to watchdog log - exec > >(multilog t s1048576 n3 "$LOG_DIR/watchdog") 2>&1 + mkdir -p "$LOG_DIR" + for _f in stdout stderr watchdog; do + rotate_on_start "$LOG_DIR/$_f.log" + done + # Plain append redirect, never a pipe: a failed write returns an error to the + # writer instead of blocking it forever. + exec >>"$LOG_DIR/watchdog.log" 2>&1 fi CHILD_PID="" +GUARD_PID="" RUNNING=true +# Background size guard: caps the log files while the child runs. Runs in its own +# subshell so the main loop stays blocked on `wait` as before. +start_size_guard() { + [[ -n "$LOG_DIR" ]] || return 0 + ( + while :; do + sleep "$GUARD_INTERVAL" + guard_size "$LOG_DIR/stdout.log" + guard_size "$LOG_DIR/stderr.log" + guard_size "$LOG_DIR/watchdog.log" + done + ) & + GUARD_PID=$! +} + +stop_size_guard() { + [[ -n "$GUARD_PID" ]] && kill "$GUARD_PID" 2>/dev/null || true + GUARD_PID="" +} + cleanup() { RUNNING=false + stop_size_guard if [[ -n "$CHILD_PID" ]] && kill -0 "$CHILD_PID" 2>/dev/null; then kill "$CHILD_PID" 2>/dev/null || true wait "$CHILD_PID" 2>/dev/null || true @@ -59,16 +121,18 @@ trap cleanup SIGTERM SIGINT while $RUNNING; do if [[ -n "$LOG_DIR" ]]; then "$@" \ - > >(multilog t s1048576 n3 "$LOG_DIR/stdout") \ - 2> >(multilog t s1048576 n3 "$LOG_DIR/stderr") & + >>"$LOG_DIR/stdout.log" \ + 2>>"$LOG_DIR/stderr.log" & else "$@" & fi CHILD_PID=$! [[ -n "$PID_FILE" ]] && echo "$CHILD_PID" > "$PID_FILE" + start_size_guard EXIT_CODE=0 wait "$CHILD_PID" || EXIT_CODE=$? CHILD_PID="" + stop_size_guard if ! $RUNNING; then break diff --git a/integrations/perception-service/src/dlserver/app.py b/integrations/perception-service/src/dlserver/app.py index 6fb34c0f3..c1ca00d63 100644 --- a/integrations/perception-service/src/dlserver/app.py +++ b/integrations/perception-service/src/dlserver/app.py @@ -227,34 +227,31 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: handler.setFormatter(logging.Formatter(LOG_FORMAT)) logging.basicConfig(level=logging.INFO, handlers=[handler]) - # Route uvicorn/fastapi logs to a separate file + # Route uvicorn/fastapi logs to a separate file. + # NOTE: "uvicorn" and "uvicorn.access" MUST share a single handler instance. + # Two RotatingFileHandlers on the same path keep independent byte counters and + # roll over independently, so one eventually unlinks the inode the other still + # holds open. On MooseFS (/workspace) writing to a deleted-but-open file returns + # EIO, which floods stderr with logging tracebacks and can wedge the process. return { "version": 1, "disable_existing_loggers": False, "formatters": { "default": {"format": LOG_FORMAT}, - "access": {"format": LOG_FORMAT}, }, "handlers": { - "default": { + "file": { "formatter": "default", "class": "logging.handlers.RotatingFileHandler", "filename": str(uvicorn_log_path), "maxBytes": 1_048_576, "backupCount": 3, }, - "access": { - "formatter": "access", - "class": "logging.handlers.RotatingFileHandler", - "filename": str(uvicorn_log_path), - "maxBytes": 1_048_576, - "backupCount": 3, - }, }, "loggers": { - "uvicorn": {"handlers": ["default"], "level": "INFO", "propagate": False}, + "uvicorn": {"handlers": ["file"], "level": "INFO", "propagate": False}, "uvicorn.error": {"level": "INFO"}, - "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False}, + "uvicorn.access": {"handlers": ["file"], "level": "INFO", "propagate": False}, }, } except Exception as e: diff --git a/integrations/perception-service/src/lbserver/app.py b/integrations/perception-service/src/lbserver/app.py index 20dc62906..ad51c3593 100644 --- a/integrations/perception-service/src/lbserver/app.py +++ b/integrations/perception-service/src/lbserver/app.py @@ -341,33 +341,31 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: handler.setFormatter(logging.Formatter(LOG_FORMAT)) logging.basicConfig(level=logging.INFO, handlers=[handler]) + # Route uvicorn/fastapi logs to a separate file. + # NOTE: "uvicorn" and "uvicorn.access" MUST share a single handler instance. + # Two RotatingFileHandlers on the same path keep independent byte counters and + # roll over independently, so one eventually unlinks the inode the other still + # holds open. On MooseFS (/workspace) writing to a deleted-but-open file returns + # EIO, which floods stderr with logging tracebacks and can wedge the process. return { "version": 1, "disable_existing_loggers": False, "formatters": { "default": {"format": LOG_FORMAT}, - "access": {"format": LOG_FORMAT}, }, "handlers": { - "default": { + "file": { "formatter": "default", "class": "logging.handlers.RotatingFileHandler", "filename": str(uvicorn_log_path), "maxBytes": 1_048_576, "backupCount": 3, }, - "access": { - "formatter": "access", - "class": "logging.handlers.RotatingFileHandler", - "filename": str(uvicorn_log_path), - "maxBytes": 1_048_576, - "backupCount": 3, - }, }, "loggers": { - "uvicorn": {"handlers": ["default"], "level": "INFO", "propagate": False}, + "uvicorn": {"handlers": ["file"], "level": "INFO", "propagate": False}, "uvicorn.error": {"level": "INFO"}, - "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False}, + "uvicorn.access": {"handlers": ["file"], "level": "INFO", "propagate": False}, }, } except Exception as e: From af085e1add4b6cd52fae14eac01dccaafdc62346 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 11:57:11 +0700 Subject: [PATCH 2/7] fix: attribute backend timeouts and trace requests end to end --- integrations/perception-service/docs/api.md | 15 ++++- .../perception-service/docs/deployment.md | 22 +++++++ .../docs/troubleshooting.md | 18 +++++ .../perception-service/nginx-ssl.conf | 39 +++++++++-- integrations/perception-service/nginx.conf | 39 +++++++++-- integrations/perception-service/src/config.py | 11 +++- .../src/core/request_context.py | 66 +++++++++++++++++++ .../perception-service/src/dlserver/app.py | 10 ++- .../perception-service/src/lbserver/app.py | 28 +++++++- 9 files changed, 230 insertions(+), 18 deletions(-) create mode 100644 integrations/perception-service/src/core/request_context.py diff --git a/integrations/perception-service/docs/api.md b/integrations/perception-service/docs/api.md index 869fad32f..f7eee2b46 100644 --- a/integrations/perception-service/docs/api.md +++ b/integrations/perception-service/docs/api.md @@ -291,8 +291,19 @@ public key as `text/plain`, or `404` if encryption is disabled. See | `400` | Bad/undecodable body, image, or audio; decryption auth-tag failure (lbserver) | | `401` | Missing/invalid `X-API-Key` | | `404` | `GET /api/crypto/public-key` when crypto disabled | -| `502` | lbserver: backend unreachable | +| `502` | lbserver: backend unreachable (connect refused -- the backend is **down**) | | `503` | Model/dependency unavailable for the requested perception | +| `504` | lbserver: backend timed out after `lb.http_timeout` (the backend is **hung** -- it accepted the connection and never replied). nginx returns its own `504` if `proxy_read_timeout` (45s) expires first | | WS `1008` | lbserver: encryption required but key exchange missing | -| WS `1011` | lbserver: key exchange failed / backend unreachable | +| WS `1011` | lbserver: key exchange failed, backend unreachable, or backend handshake timed out | + +Every response carries `X-Request-ID` -- echoed if the caller sent one, otherwise +minted by nginx. The same id appears in the nginx access log (`rid=`) and in every +lbserver and dlserver log line, so one request can be traced end to end: + +```bash +grep -r "$REQUEST_ID" /var/log/nginx/ /workspace/logs/ +``` + +If it matches nothing, the request never reached this host. diff --git a/integrations/perception-service/docs/deployment.md b/integrations/perception-service/docs/deployment.md index 6d10c2a89..f51871c79 100644 --- a/integrations/perception-service/docs/deployment.md +++ b/integrations/perception-service/docs/deployment.md @@ -195,6 +195,28 @@ run-with-restart.sh [OPTIONS] -- COMMAND [ARGS...] Sending `SIGTERM` to the wrapper gracefully stops the inner process and exits. +### Timeout ladder + +Deadlines shrink as you go inward, so the innermost layer gives up first and every +layer above it reports an attributable failure rather than inventing its own: + +| Layer | Setting | Value | +|-------|---------|-------| +| HAL (device) | client read timeout | 10-15s | +| nginx | `proxy_read_timeout` (`nginx.conf`) | 45s | +| nginx | `proxy_connect_timeout` | 5s | +| lbserver | `lb.http_timeout` (`config.py`) | 30s | +| lbserver | `lb.ws_open_timeout` | 30s | + +**Never set two adjacent layers to the same value.** nginx and lbserver were both +120s, which made the winner nondeterministic: a hung backend surfaced as `504` +sometimes and `500` other times. lbserver must expire first so it can log which +backend timed out and return `504`. + +HAL's 10-15s sits *inside* the whole chain, so the device still gives up before +nginx does. Raising it above 45s would make failures attributable end to end, but +costs realtime responsiveness -- that is a device-side decision, deployed by OTA. + ### PID files and logs | File | Purpose | diff --git a/integrations/perception-service/docs/troubleshooting.md b/integrations/perception-service/docs/troubleshooting.md index cdcb32de5..4465d612d 100644 --- a/integrations/perception-service/docs/troubleshooting.md +++ b/integrations/perception-service/docs/troubleshooting.md @@ -53,6 +53,24 @@ curl -s -H "X-API-Key: $API_KEY" http://127.0.0.1:8899/hal/api/dl/health A 401 is a liveness signal, not a failure. Only the `200` body confirms models are actually loaded, which is why the autostart probe checks for it. +## 1b. Triaging a reported 5xx + +Start from the request id in the report. One command decides which layer to look at: + +```bash +grep -r "$REQUEST_ID" /var/log/nginx/ /workspace/logs/ || echo "NEVER REACHED THIS HOST" +``` + +| nginx access line | Meaning | Next step | +|---|---|---| +| *(no match anywhere)* | Never arrived -- died at the caller, Cloudflare or the ingress | Nothing to do here. Check the caller's own logs. | +| `client=504 upstream=-` | Backend **hung**: accepted the connection, never replied | `cat /proc/$(cat /tmp/dlserver.pid)/wchan` -- `pipe_write` means a frozen event loop | +| `client=502 upstream=-` | Backend **down**: connect refused | Did it restart? Check `watchdog.log` | +| `client=200 upstream=200` | Healthy here | Failure is downstream -- client timeout or transport | + +`urt=` is the upstream response time; compare it against the ladder in +[deployment.md](deployment.md#timeout-ladder). + ## 2. Reading the logs Logs are plain text files. No decoding is needed: diff --git a/integrations/perception-service/nginx-ssl.conf b/integrations/perception-service/nginx-ssl.conf index a079a7b2a..90b810c3e 100644 --- a/integrations/perception-service/nginx-ssl.conf +++ b/integrations/perception-service/nginx-ssl.conf @@ -6,7 +6,25 @@ events { } http { - access_log /var/log/nginx/access.log; + # Carry an inbound X-Request-ID through the whole chain, or mint one. This is + # what makes a failure greppable across nginx -> lbserver -> dlserver instead + # of needing wall-clock correlation across four separate logs. + map $http_x_request_id $req_id { + default $http_x_request_id; + '' $request_id; + } + + # $upstream_status is the discriminator that tells the three failure shapes apart: + # client=504 upstream=- backend hung (accepted the connection, never replied) + # client=502 upstream=- backend down (connect refused) + # no line at all never reached this box (Cloudflare / ingress / caller) + log_format upstream_detail + '$remote_addr $host "$request" ' + 'client=$status upstream=$upstream_status ' + 'rt=$request_time urt=$upstream_response_time ' + 'addr=$upstream_addr rid=$req_id "$http_user_agent"'; + + access_log /var/log/nginx/access.log upstream_detail; error_log /var/log/nginx/error.log; map $http_upgrade $connection_upgrade { @@ -31,8 +49,13 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; - proxy_read_timeout 120s; - proxy_send_timeout 120s; + proxy_set_header X-Request-ID $req_id; + add_header X-Request-ID $req_id always; + # Must exceed lb.http_timeout (30s) so lbserver fails first and can + # attribute the failure to its backend. Equal timeouts are a race. + proxy_connect_timeout 5s; + proxy_read_timeout 45s; + proxy_send_timeout 45s; } location /lelamp/ { @@ -42,8 +65,13 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; - proxy_read_timeout 120s; - proxy_send_timeout 120s; + proxy_set_header X-Request-ID $req_id; + add_header X-Request-ID $req_id always; + # Must exceed lb.http_timeout (30s) so lbserver fails first and can + # attribute the failure to its backend. Equal timeouts are a race. + proxy_connect_timeout 5s; + proxy_read_timeout 45s; + proxy_send_timeout 45s; } location /jupyter/ { @@ -53,6 +81,7 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; + proxy_set_header X-Request-ID $req_id; proxy_read_timeout 3600s; proxy_send_timeout 3600s; } diff --git a/integrations/perception-service/nginx.conf b/integrations/perception-service/nginx.conf index 6b43ca77e..972d76b88 100644 --- a/integrations/perception-service/nginx.conf +++ b/integrations/perception-service/nginx.conf @@ -6,7 +6,25 @@ events { } http { - access_log /var/log/nginx/access.log; + # Carry an inbound X-Request-ID through the whole chain, or mint one. This is + # what makes a failure greppable across nginx -> lbserver -> dlserver instead + # of needing wall-clock correlation across four separate logs. + map $http_x_request_id $req_id { + default $http_x_request_id; + '' $request_id; + } + + # $upstream_status is the discriminator that tells the three failure shapes apart: + # client=504 upstream=- backend hung (accepted the connection, never replied) + # client=502 upstream=- backend down (connect refused) + # no line at all never reached this box (Cloudflare / ingress / caller) + log_format upstream_detail + '$remote_addr $host "$request" ' + 'client=$status upstream=$upstream_status ' + 'rt=$request_time urt=$upstream_response_time ' + 'addr=$upstream_addr rid=$req_id "$http_user_agent"'; + + access_log /var/log/nginx/access.log upstream_detail; error_log /var/log/nginx/error.log; map $http_upgrade $connection_upgrade { @@ -28,8 +46,13 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; - proxy_read_timeout 120s; - proxy_send_timeout 120s; + proxy_set_header X-Request-ID $req_id; + add_header X-Request-ID $req_id always; + # Must exceed lb.http_timeout (30s) so lbserver fails first and can + # attribute the failure to its backend. Equal timeouts are a race. + proxy_connect_timeout 5s; + proxy_read_timeout 45s; + proxy_send_timeout 45s; } location /lelamp/ { @@ -39,8 +62,13 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; - proxy_read_timeout 120s; - proxy_send_timeout 120s; + proxy_set_header X-Request-ID $req_id; + add_header X-Request-ID $req_id always; + # Must exceed lb.http_timeout (30s) so lbserver fails first and can + # attribute the failure to its backend. Equal timeouts are a race. + proxy_connect_timeout 5s; + proxy_read_timeout 45s; + proxy_send_timeout 45s; } location /jupyter/ { @@ -50,6 +78,7 @@ http { proxy_set_header Connection $connection_upgrade; proxy_set_header Host $host; proxy_set_header X-Real-IP $remote_addr; + proxy_set_header X-Request-ID $req_id; proxy_read_timeout 3600s; proxy_send_timeout 3600s; } diff --git a/integrations/perception-service/src/config.py b/integrations/perception-service/src/config.py index 2c82a7c17..c0f99b747 100644 --- a/integrations/perception-service/src/config.py +++ b/integrations/perception-service/src/config.py @@ -143,8 +143,15 @@ class LBSetting(BaseModel): host: str = "0.0.0.0" port: int = 7999 internal_prefix: str = "" - http_timeout: float = 120.0 # seconds, httpx client timeout for backend requests - ws_open_timeout: float = 120.0 # seconds, websocket handshake timeout to backend + # Deadlines must shrink as you go inward, so the innermost layer gives up first + # and the outer layers report an attributable failure. nginx sits in front at + # proxy_read_timeout 45s; HAL clients on the device use 10-15s. Measured owlv2 + # service time is well under 5s, so 30s is ~6x headroom while still failing long + # before nginx does. Equal timeouts (both were 120s) are a race with a + # nondeterministic winner and were why a hung backend surfaced as 504 sometimes + # and 500 other times. + http_timeout: float = 30.0 # seconds, httpx client timeout for backend requests + ws_open_timeout: float = 30.0 # seconds, websocket handshake timeout to backend class Settings(BaseSettings): diff --git a/integrations/perception-service/src/core/request_context.py b/integrations/perception-service/src/core/request_context.py new file mode 100644 index 000000000..7f054bbd4 --- /dev/null +++ b/integrations/perception-service/src/core/request_context.py @@ -0,0 +1,66 @@ +"""Request-ID propagation shared by dlserver and lbserver. + +A single id follows one request across nginx -> lbserver -> dlserver so an +operator-visible failure can be traced with one grep instead of correlating +wall-clock timestamps across four logs. + +Install order matters: `install_request_id_logging()` must run before any log +record is emitted, because LOG_FORMAT references %(request_id)s and a record +without that attribute raises during formatting. Using a LogRecord factory +(rather than a logging.Filter) guarantees *every* record has the attribute, +including ones from third-party libraries that never pass through our handlers. +""" + +from __future__ import annotations + +import contextvars +import logging +import uuid +from collections.abc import Awaitable, Callable +from typing import TYPE_CHECKING + +if TYPE_CHECKING: # pragma: no cover + from fastapi import Request, Response + +REQUEST_ID_HEADER = "x-request-id" +NO_REQUEST_ID = "-" + +request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar( + "request_id", default=NO_REQUEST_ID +) + +_installed = False + + +def install_request_id_logging() -> None: + """Make every LogRecord carry `request_id`. Idempotent.""" + global _installed + if _installed: + return + old_factory = logging.getLogRecordFactory() + + def factory(*args: object, **kwargs: object) -> logging.LogRecord: + record = old_factory(*args, **kwargs) + record.request_id = request_id_var.get() + return record + + logging.setLogRecordFactory(factory) + _installed = True + + +def new_request_id() -> str: + return uuid.uuid4().hex + + +async def request_id_middleware( + request: "Request", call_next: Callable[["Request"], Awaitable["Response"]] +) -> "Response": + """Bind the inbound X-Request-ID (or mint one) for the duration of the request.""" + rid = request.headers.get(REQUEST_ID_HEADER) or new_request_id() + token = request_id_var.set(rid) + try: + response = await call_next(request) + response.headers[REQUEST_ID_HEADER] = rid + return response + finally: + request_id_var.reset(token) diff --git a/integrations/perception-service/src/dlserver/app.py b/integrations/perception-service/src/dlserver/app.py index c1ca00d63..642dc6f73 100644 --- a/integrations/perception-service/src/dlserver/app.py +++ b/integrations/perception-service/src/dlserver/app.py @@ -47,6 +47,10 @@ set_object_models, set_pose_model, ) +from core.request_context import ( + install_request_id_logging, + request_id_middleware, +) from factory import ( build_action_perception, build_audio_embedder, @@ -56,7 +60,10 @@ build_pose_perception, ) -LOG_FORMAT = "%(asctime)s [%(name)s] %(levelname)s: %(message)s" +LOG_FORMAT = "%(asctime)s [%(name)s] [%(request_id)s] %(levelname)s: %(message)s" + +# Must run before any record is emitted: LOG_FORMAT references %(request_id)s. +install_request_id_logging() logger = logging.getLogger(__name__) # --- Auth --- @@ -177,6 +184,7 @@ async def lifespan(app: FastAPI): # --- App + Routers --- app = FastAPI(title="DL Backend", lifespan=lifespan) +app.middleware("http")(request_id_middleware) # Existing perceptions — /hal/api/dl/ prefix app.include_router(action_ws_router, prefix="/hal/api/dl") diff --git a/integrations/perception-service/src/lbserver/app.py b/integrations/perception-service/src/lbserver/app.py index ad51c3593..b1e34dde0 100644 --- a/integrations/perception-service/src/lbserver/app.py +++ b/integrations/perception-service/src/lbserver/app.py @@ -34,9 +34,16 @@ from lbserver.routes.crypto import router as crypto_router from lbserver.utils import RoundRobin from lbserver.utils.crypto import encrypt_http_response, try_decrypt_http_body +from core.request_context import ( + install_request_id_logging, + request_id_middleware, +) from lbserver.utils.state import get_crypto, set_crypto -LOG_FORMAT = "%(asctime)s [%(name)s] %(levelname)s: %(message)s" +LOG_FORMAT = "%(asctime)s [%(name)s] [%(request_id)s] %(levelname)s: %(message)s" + +# Must run before any record is emitted: LOG_FORMAT references %(request_id)s. +install_request_id_logging() logger = logging.getLogger("lbserver") @@ -75,6 +82,7 @@ async def _lifespan(app: FastAPI): app = FastAPI(title="DL Backend Load Balancer", lifespan=_lifespan) +app.middleware("http")(request_id_middleware) app.include_router(crypto_router, prefix="/api/crypto") @@ -116,8 +124,18 @@ async def proxy_http(request: Request, path: str) -> Response: params=dict(request.query_params), content=body, ) - except httpx.ConnectError: - logger.error("[HTTP] Backend unreachable: %s", backend) + # Order matters: TimeoutException is a subclass of RequestError, so it must be + # caught first. A hung-but-listening backend completes the TCP handshake (the + # kernel does it, into the accept queue), so ConnectError never fires and the + # read times out instead -- previously that escaped uncaught and Starlette + # rendered a generic 500, hiding the fact that the backend was the problem. + except httpx.TimeoutException: + logger.error( + "[HTTP] Backend timed out after %ss: %s", settings.lb.http_timeout, backend + ) + raise HTTPException(status_code=504, detail=f"Backend timed out: {backend}") + except httpx.RequestError as e: + logger.error("[HTTP] Backend unreachable: %s -- %s", backend, e) raise HTTPException(status_code=502, detail=f"Backend unreachable: {backend}") content = resp.content @@ -300,6 +318,10 @@ async def backend_to_client() -> None: t.cancel() await asyncio.gather(*tasks, return_exceptions=True) + except TimeoutError as e: + # websockets raises this on open_timeout; it is what a hung backend produces. + logger.error("[WS] Backend handshake timed out: %s — %s", backend, e) + await client_ws.close(code=1011, reason=f"Backend timed out: {backend}") except (websockets.exceptions.InvalidStatus, OSError) as e: logger.error("[WS] Backend connection failed: %s — %s", backend, e) await client_ws.close(code=1011, reason=f"Backend unreachable: {backend}") From 1b901cc3e51d0ed44800cc10eb7154575eba64c6 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 13:15:23 +0700 Subject: [PATCH 3/7] fix: verify shutdown, guard single instance, and detect a frozen server --- integrations/perception-service/Makefile | 36 ++----- integrations/perception-service/docs/api.md | 9 ++ .../perception-service/docs/deployment.md | 59 +++++++++++ .../perception-service/nginx-ssl.conf | 8 ++ integrations/perception-service/nginx.conf | 8 ++ .../scripts/run-with-restart.sh | 58 +++++++++++ .../perception-service/scripts/stop-tree.sh | 98 +++++++++++++++++++ .../perception-service/src/core/livez.py | 25 +++++ .../src/core/request_context.py | 45 +++++++++ .../perception-service/src/dlserver/app.py | 23 ++++- .../perception-service/src/lbserver/app.py | 25 ++++- 11 files changed, 366 insertions(+), 28 deletions(-) create mode 100755 integrations/perception-service/scripts/stop-tree.sh create mode 100644 integrations/perception-service/src/core/livez.py diff --git a/integrations/perception-service/Makefile b/integrations/perception-service/Makefile index 60e33815a..dfc87b644 100644 --- a/integrations/perception-service/Makefile +++ b/integrations/perception-service/Makefile @@ -122,16 +122,18 @@ start-runpod-master: start-nginx start-runpod-dlserver start-runpod-lbserver start-runpod-master-ssl: start-nginx-ssl start-runpod-dlserver start-runpod-lbserver start-runpod-slave: start-nginx stop-runpod-dlserver install - @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ + @$(SET_TRT_LD_PATH); nohup setsid bash scripts/run-with-restart.sh \ --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ + --probe-url http://127.0.0.1:$(LBSERVER_PORT)/livez \ --log-dir /workspace/logs/dlserver -- \ python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver \ /dev/null 2>&1 & @echo "dlserver started on port $(LBSERVER_PORT) (slave, no LB)" start-runpod-slave-ssl: start-nginx-ssl stop-runpod-dlserver install - @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ + @$(SET_TRT_LD_PATH); nohup setsid bash scripts/run-with-restart.sh \ --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ + --probe-url http://127.0.0.1:$(LBSERVER_PORT)/livez \ --log-dir /workspace/logs/dlserver -- \ python -m dlserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/dlserver \ /dev/null 2>&1 & @@ -176,46 +178,28 @@ start-nginx-ssl: gen-ssl-cert stop-nginx nginx -c /etc/nginx/perception-service-nginx-ssl.conf start-runpod-dlserver: install stop-runpod-dlserver - @$(SET_TRT_LD_PATH); nohup bash scripts/run-with-restart.sh \ + @$(SET_TRT_LD_PATH); nohup setsid bash scripts/run-with-restart.sh \ --pid-file $(DLSERVER_PID) --wrapper-pid-file $(DLSERVER_WRAPPER_PID) --cooldown 5 \ + --probe-url http://127.0.0.1:$(DLSERVER_PORT)/livez \ --log-dir /workspace/logs/dlserver -- \ python -m dlserver --host 127.0.0.1 --port $(DLSERVER_PORT) --log-dir /workspace/logs/dlserver \ /dev/null 2>&1 & @echo "dlserver started on port $(DLSERVER_PORT) (auto-restart enabled)" stop-runpod-dlserver: - @if [ -f $(DLSERVER_WRAPPER_PID) ]; then \ - kill $$(cat $(DLSERVER_WRAPPER_PID)) 2>/dev/null || true; \ - rm -f $(DLSERVER_WRAPPER_PID); \ - fi - @if [ -f $(DLSERVER_PID) ]; then \ - kill $$(cat $(DLSERVER_PID)) 2>/dev/null || true; \ - rm -f $(DLSERVER_PID); \ - fi - @rm -f /workspace/logs/dlserver/stderr/lock - @sleep 2 - @echo "dlserver stopped" + @bash scripts/stop-tree.sh dlserver $(DLSERVER_PORT) $(DLSERVER_WRAPPER_PID) $(DLSERVER_PID) start-runpod-lbserver: install-lb stop-runpod-lbserver - @nohup bash scripts/run-with-restart.sh \ + @nohup setsid bash scripts/run-with-restart.sh \ --pid-file $(LBSERVER_PID) --wrapper-pid-file $(LBSERVER_WRAPPER_PID) --cooldown 5 \ + --probe-url http://127.0.0.1:$(LBSERVER_PORT)/livez \ --log-dir /workspace/logs/lbserver -- \ python -m lbserver --host 127.0.0.1 --port $(LBSERVER_PORT) --log-dir /workspace/logs/lbserver \ /dev/null 2>&1 & @echo "lbserver started on port $(LBSERVER_PORT) (auto-restart enabled)" stop-runpod-lbserver: - @if [ -f $(LBSERVER_WRAPPER_PID) ]; then \ - kill $$(cat $(LBSERVER_WRAPPER_PID)) 2>/dev/null || true; \ - rm -f $(LBSERVER_WRAPPER_PID); \ - fi - @if [ -f $(LBSERVER_PID) ]; then \ - kill $$(cat $(LBSERVER_PID)) 2>/dev/null || true; \ - rm -f $(LBSERVER_PID); \ - fi - @rm -f /workspace/logs/lbserver/stderr/lock - @sleep 2 - @echo "lbserver stopped" + @bash scripts/stop-tree.sh lbserver $(LBSERVER_PORT) $(LBSERVER_WRAPPER_PID) $(LBSERVER_PID) start-jupyter: @if ! command -v jupyter-lab > /dev/null 2>&1; then \ diff --git a/integrations/perception-service/docs/api.md b/integrations/perception-service/docs/api.md index f7eee2b46..2651014a8 100644 --- a/integrations/perception-service/docs/api.md +++ b/integrations/perception-service/docs/api.md @@ -286,6 +286,15 @@ public key as `text/plain`, or `404` if encryption is disabled. See ## Error responses +### `GET /livez` (both servers) + +Liveness only: returns `200 {"status":"alive"}` if a coroutine can still be +scheduled. No auth, no model checks, no downstream calls. Restricted to localhost +at the nginx layer -- it exists for the watchdog, not for callers. + +Do not confuse it with `GET /hal/api/dl/health`, which is *readiness*: it needs an +API key and reports which models finished loading. + | Code | When | |------|------| | `400` | Bad/undecodable body, image, or audio; decryption auth-tag failure (lbserver) | diff --git a/integrations/perception-service/docs/deployment.md b/integrations/perception-service/docs/deployment.md index f51871c79..e00a132fb 100644 --- a/integrations/perception-service/docs/deployment.md +++ b/integrations/perception-service/docs/deployment.md @@ -183,6 +183,8 @@ run-with-restart.sh [OPTIONS] -- COMMAND [ARGS...] --pid-file PATH inner process PID (for stop targets) --wrapper-pid-file PATH watchdog's own PID --cooldown SECONDS wait between restarts (default: 5) + --probe-url URL liveness probe; after PROBE_FAILURES consecutive + failures the child is SIGKILLed and restarted --log-dir PATH plain-file logging (never a pipe -- a blocked pipe can freeze the server): log-dir/stdout.log server stdout @@ -195,6 +197,63 @@ run-with-restart.sh [OPTIONS] -- COMMAND [ARGS...] Sending `SIGTERM` to the wrapper gracefully stops the inner process and exits. +### Liveness watchdog + +`wait` alone only fires when the child **exits**. A frozen child never exits, so +the wrapper waited 3.5h on 2026-08-10 and ~50min on 2026-08-17 while the port +stayed bound and every port-based check reported green. + +The wrapper now polls `--probe-url` alongside `wait`: + +| Env var | Default | Meaning | +|---------|---------|---------| +| `PROBE_INTERVAL` | 10s | between probes | +| `PROBE_TIMEOUT` | 5s | per-probe curl timeout | +| `PROBE_FAILURES` | 6 | consecutive failures before acting (~60s) | +| `PROBE_GRACE` | 180s | no probing for this long after start | + +`PROBE_GRACE` is not optional padding: dlserver takes ~2-3 minutes to load models +(08:51 -> 08:53 on the real box). Probing during that window would kill it before +it ever served a request, and it would never finish booting. + +On `PROBE_FAILURES` consecutive failures the wrapper sends **SIGKILL**, not +SIGTERM. A hung uvicorn absorbs SIGTERM: its handler only sets `should_exit`, and +the only thing that can act on that flag is the event loop -- the thing that is +stuck. + +**Probe `/livez`, never `/health`.** `/livez` takes no auth and checks nothing but +the event loop. `/hal/api/dl/health` is a *readiness* check -- it reports whether +the models loaded, needs an API key, and would restart-loop the server during a +slow start or after a key rotation. Readiness failing means "route traffic +elsewhere"; liveness failing means "restart this process". + +### Stopping + +`make stop-runpod-*` runs `scripts/stop-tree.sh`, which: + +1. resolves the real holder from the **listening socket**, not just `/tmp/*.pid` + (a failed start overwrites those with its own dead PIDs) +2. escalates **SIGTERM -> SIGTERM -> SIGKILL**, polling up to 10s per round +3. kills whole **process groups** -- start targets use `setsid` so each wrapper + owns its group, covering the child, size guard and liveness probe +4. **exits non-zero if anything survives**, so `start` refuses to run on a dirty + slate rather than dying later on `EADDRINUSE` + +A process sharing the caller's own group (an instance from a build predating +`setsid`) is killed individually -- killing that group would take down `make` +itself mid-stop. + +### Single instance per log directory + +Each server takes an exclusive `flock` on `/.instance.lock` before it +rotates anything, and exits **3** if another instance holds it. The startup +rotation renames and unlinks every matching log file unconditionally, so without +this a second start yanked the log files out from under a running instance -- +which is what made the 2026-08-10 outage unrecoverable. + +`flock` rather than a PID file: it is race-free, and the kernel releases it +however the holder dies, including SIGKILL. + ### Timeout ladder Deadlines shrink as you go inward, so the innermost layer gives up first and every diff --git a/integrations/perception-service/nginx-ssl.conf b/integrations/perception-service/nginx-ssl.conf index 90b810c3e..7d4f94486 100644 --- a/integrations/perception-service/nginx-ssl.conf +++ b/integrations/perception-service/nginx-ssl.conf @@ -42,6 +42,14 @@ http { client_max_body_size 50M; # All traffic → port 7999 (LB on master, dlserver on slave) + # Liveness is for the local watchdog only. Blocking it here keeps the + # endpoint off the public surface while curl from the box still works, + # because the watchdog talks to 127.0.0.1:PORT directly, not through nginx. + location = /livez { + deny all; + access_log off; + } + location / { proxy_pass http://127.0.0.1:7999/; proxy_http_version 1.1; diff --git a/integrations/perception-service/nginx.conf b/integrations/perception-service/nginx.conf index 972d76b88..59bc03b64 100644 --- a/integrations/perception-service/nginx.conf +++ b/integrations/perception-service/nginx.conf @@ -39,6 +39,14 @@ http { client_max_body_size 50M; # All traffic → port 7999 (LB on master, dlserver on slave) + # Liveness is for the local watchdog only. Blocking it here keeps the + # endpoint off the public surface while curl from the box still works, + # because the watchdog talks to 127.0.0.1:PORT directly, not through nginx. + location = /livez { + deny all; + access_log off; + } + location / { proxy_pass http://127.0.0.1:7999/; proxy_http_version 1.1; diff --git a/integrations/perception-service/scripts/run-with-restart.sh b/integrations/perception-service/scripts/run-with-restart.sh index 78927389b..86948a2a5 100755 --- a/integrations/perception-service/scripts/run-with-restart.sh +++ b/integrations/perception-service/scripts/run-with-restart.sh @@ -5,6 +5,11 @@ # --pid-file PATH: the inner process PID is written here on each start. # --wrapper-pid-file PATH: this wrapper's own PID is written here once at startup. # --cooldown SECONDS: wait between restarts (default: 5). +# --probe-url URL: if set, poll this every PROBE_INTERVAL seconds. After +# PROBE_FAILURES consecutive failures the child is killed +# with -9 and the restart loop takes over. Use a liveness +# endpoint (/livez): it must not check models, auth or any +# downstream service, or a slow start becomes a restart loop. # --log-dir PATH: if set, stdout → log-dir/stdout.log, stderr → log-dir/stderr.log # and watchdog messages → log-dir/watchdog.log. # Plain files on purpose: a pipe to multilog can block the @@ -16,6 +21,7 @@ set -euo pipefail COOLDOWN=5 +PROBE_URL="" PID_FILE="" WRAPPER_PID_FILE="" LOG_DIR="" @@ -23,6 +29,7 @@ LOG_DIR="" while [[ $# -gt 0 ]]; do case "$1" in --cooldown) COOLDOWN="$2"; shift 2 ;; + --probe-url) PROBE_URL="$2"; shift 2 ;; --pid-file) PID_FILE="$2"; shift 2 ;; --wrapper-pid-file) WRAPPER_PID_FILE="$2"; shift 2 ;; --log-dir) LOG_DIR="$2"; shift 2 ;; @@ -44,6 +51,14 @@ MAX_LOG_BYTES=${MAX_LOG_BYTES:-8388608} # 8 MiB LOG_BACKUPS=3 GUARD_INTERVAL=${GUARD_INTERVAL:-60} # seconds between size checks +# Liveness probe. Deliberately conservative: a probe that is too eager turns a slow +# start into an endless restart loop. +PROBE_INTERVAL=${PROBE_INTERVAL:-10} # seconds between probes +PROBE_TIMEOUT=${PROBE_TIMEOUT:-5} # per-probe curl timeout +PROBE_FAILURES=${PROBE_FAILURES:-6} # consecutive failures before acting (~60s) +PROBE_GRACE=${PROBE_GRACE:-180} # seconds after start before probing at all; + # dlserver needs ~2-3 min to load its models + # Rename FILE aside on startup, keeping LOG_BACKUPS generations. Safe here because # no process holds these files open yet. rotate_on_start() { @@ -85,6 +100,7 @@ fi CHILD_PID="" GUARD_PID="" +PROBE_PID="" RUNNING=true # Background size guard: caps the log files while the child runs. Runs in its own @@ -102,6 +118,45 @@ start_size_guard() { GUARD_PID=$! } +# Watches liveness while the child runs. `wait` alone only fires when the child +# EXITS -- a frozen child never exits, so the wrapper sat in do_wait for 3.5h on +# 2026-08-10 and ~50min on 2026-08-17 while the port stayed bound and green. +# +# kill -9 is mandatory: a hung uvicorn absorbs SIGTERM. Its handler only sets +# should_exit, and the only thing that can act on that flag is the event loop -- +# which is the thing that is stuck. +start_liveness_probe() { + [[ -n "$PROBE_URL" ]] || return 0 + local target=$1 + ( + sleep "$PROBE_GRACE" + local fails=0 + while :; do + if curl -fsS -m "$PROBE_TIMEOUT" -o /dev/null "$PROBE_URL" 2>/dev/null; then + if (( fails > 0 )); then + echo "[watchdog] probe recovered after $fails failure(s)" + fi + fails=0 + else + fails=$(( fails + 1 )) + echo "[watchdog] probe failed ($fails/$PROBE_FAILURES): $PROBE_URL" + if (( fails >= PROBE_FAILURES )); then + echo "[watchdog] unresponsive after $fails probes; SIGKILL $target" + kill -9 "$target" 2>/dev/null || true + return 0 + fi + fi + sleep "$PROBE_INTERVAL" + done + ) & + PROBE_PID=$! +} + +stop_liveness_probe() { + [[ -n "$PROBE_PID" ]] && kill "$PROBE_PID" 2>/dev/null || true + PROBE_PID="" +} + stop_size_guard() { [[ -n "$GUARD_PID" ]] && kill "$GUARD_PID" 2>/dev/null || true GUARD_PID="" @@ -109,6 +164,7 @@ stop_size_guard() { cleanup() { RUNNING=false + stop_liveness_probe stop_size_guard if [[ -n "$CHILD_PID" ]] && kill -0 "$CHILD_PID" 2>/dev/null; then kill "$CHILD_PID" 2>/dev/null || true @@ -129,9 +185,11 @@ while $RUNNING; do CHILD_PID=$! [[ -n "$PID_FILE" ]] && echo "$CHILD_PID" > "$PID_FILE" start_size_guard + start_liveness_probe "$CHILD_PID" EXIT_CODE=0 wait "$CHILD_PID" || EXIT_CODE=$? CHILD_PID="" + stop_liveness_probe stop_size_guard if ! $RUNNING; then diff --git a/integrations/perception-service/scripts/stop-tree.sh b/integrations/perception-service/scripts/stop-tree.sh new file mode 100755 index 000000000..24b4e825c --- /dev/null +++ b/integrations/perception-service/scripts/stop-tree.sh @@ -0,0 +1,98 @@ +#!/usr/bin/env bash +# Stop a perception-service process tree and PROVE it stopped. +# +# Usage: stop-tree.sh NAME PORT WRAPPER_PID_FILE PID_FILE +# +# The old `make stop-runpod-*` bodies sent one SIGTERM to two PIDs read from +# /tmp, slept 2 seconds, and printed "stopped" unconditionally. Three problems, +# all of which cost real outage time: +# +# 1. SIGTERM cannot stop a hung server. uvicorn's handler only sets +# should_exit, and the only thing that can act on it is the event loop -- +# the thing that is stuck. Escalation to -9 is required. +# 2. The pid files are least trustworthy exactly when stop matters most: a +# failed start overwrites them with its own dead PIDs (2026-08-10). +# The listening socket is authoritative, so ask the kernel instead. +# 3. Reporting success without checking meant the next `start` died on +# EADDRINUSE with no clue why. This exits non-zero instead. +set -uo pipefail + +NAME=${1:?usage: stop-tree.sh NAME PORT WRAPPER_PID_FILE PID_FILE} +PORT=${2:?} +WPID_FILE=${3:?} +PID_FILE=${4:?} + +# Every PID belonging to this service, from every source we have. The process +# group covers anything the wrapper spawned (child, size guard, liveness probe); +# the port and pid files catch instances started by an older build that predates +# setsid. +collect() { + { + ss -lntpH "sport = :$PORT" 2>/dev/null | grep -oE 'pid=[0-9]+' | cut -d= -f2 + [[ -r "$WPID_FILE" ]] && cat "$WPID_FILE" + [[ -r "$PID_FILE" ]] && cat "$PID_FILE" + pgrep -f "run-with-restart.sh .*--log-dir /workspace/logs/$NAME" 2>/dev/null + pgrep -f "python -m $NAME " 2>/dev/null + } 2>/dev/null | grep -E '^[0-9]+$' | sort -un +} + +# Expand each PID to its whole process group so nothing is orphaned. +# +# SAFETY: never return our own process group. Start targets use `setsid`, so a +# current-build wrapper always has a group of its own. But an instance started by +# an older build shares the group of whatever launched it -- make, or the +# operator's shell. Killing that group would take down make (and this script) +# mid-stop, which looks exactly like a successful stop while leaving the server +# running. Such PIDs are still killed individually below. +expand_groups() { + local pid pgid self + self=$(ps -o pgid= -p $$ 2>/dev/null | tr -d ' ') + for pid in "$@"; do + pgid=$(ps -o pgid= -p "$pid" 2>/dev/null | tr -d ' ') + [[ -z "$pgid" ]] && continue + if [[ "$pgid" == "$self" ]]; then + echo "[$NAME] pid $pid shares our process group ($pgid); killing it" \ + "individually instead of by group" >&2 + continue + fi + (( pgid > 1 )) && echo "$pgid" + done | sort -un +} + +# Test collect's OUTPUT, never its exit status. `set -o pipefail` is on and the +# last producer inside collect is pgrep, which exits 1 when it matches nothing -- +# so collect can exit non-zero while still having printed live PIDs. Keying on the +# status made `alive` report "dead" for a live process, which broke out of the +# escalation loop after the first SIGTERM and meant KILL was never sent. +alive() { [[ -n "$(collect | tr -d '[:space:]')" ]]; } + +# No mapfile/readarray here: this script has to work in a crisis, so it must not +# assume bash >= 4. +for sig in TERM TERM KILL; do + pids=$(collect | tr '\n' ' ') + [[ -z "${pids// /}" ]] && break + # shellcheck disable=SC2086 + pgids=$(expand_groups $pids | tr '\n' ' ') + + echo "[$NAME] SIG$sig -> pids: ${pids:-none} groups: ${pgids:-none}" + for pgid in $pgids; do kill -"$sig" -- "-$pgid" 2>/dev/null || true; done + for pid in $pids; do kill -"$sig" "$pid" 2>/dev/null || true; done + + for _ in $(seq 20); do # up to 10s per round + sleep 0.5 + alive || break 2 + done +done + +rm -f "$WPID_FILE" "$PID_FILE" + +# Verify. Never claim success we have not proven. +leftover=$(collect | tr '\n' ' ') +if [[ -n "${leftover// /}" ]] || ss -lntH "sport = :$PORT" 2>/dev/null | grep -q .; then + echo "[$NAME] FAILED to stop cleanly." >&2 + echo "[$NAME] survivors: ${leftover:-none}" >&2 + ss -lntp "sport = :$PORT" >&2 2>/dev/null || true + exit 1 +fi + +echo "[$NAME] stopped, port $PORT released" diff --git a/integrations/perception-service/src/core/livez.py b/integrations/perception-service/src/core/livez.py new file mode 100644 index 000000000..b48d7e8fe --- /dev/null +++ b/integrations/perception-service/src/core/livez.py @@ -0,0 +1,25 @@ +"""Liveness endpoint shared by dlserver and lbserver. + +Liveness answers exactly one question: *is this process still executing?* It must +therefore do as little as possible -- no auth, no model checks, no downstream +calls, no locks, no I/O. If this handler cannot produce a response, the asyncio +event loop is not running, which is the failure this endpoint exists to catch +(dlserver 2026-08-17: alive, port bound, LISTEN, event loop blocked in +pipe_write, every port-based check green for 50 minutes). + +This is deliberately NOT the same as readiness. dlserver's /hal/api/dl/health +reports whether the models finished loading; a watchdog that restarted on *that* +would kill the process during its ~2 minute model load and never finish booting. +Readiness failing means "route traffic elsewhere"; liveness failing means +"restart this process". +""" + +from fastapi import APIRouter + +router = APIRouter() + + +@router.get("/livez") +async def livez() -> dict[str, str]: + """Return 200 iff a coroutine can still be scheduled on the event loop.""" + return {"status": "alive"} diff --git a/integrations/perception-service/src/core/request_context.py b/integrations/perception-service/src/core/request_context.py index 7f054bbd4..1d1b1e066 100644 --- a/integrations/perception-service/src/core/request_context.py +++ b/integrations/perception-service/src/core/request_context.py @@ -15,6 +15,7 @@ import contextvars import logging +import os import uuid from collections.abc import Awaitable, Callable from typing import TYPE_CHECKING @@ -64,3 +65,47 @@ async def request_id_middleware( return response finally: request_id_var.reset(token) + + +# --------------------------------------------------------------------------- +# Single-instance guard +# --------------------------------------------------------------------------- + + +class InstanceAlreadyRunning(RuntimeError): + """Another process already holds the log-directory lock.""" + + +def acquire_instance_lock(log_dir: str) -> "object": + """Take an exclusive, non-blocking lock on /.instance.lock. + + Must be called BEFORE the startup log rotation. That rotation renames and + unlinks every matching log file with no liveness check, so starting a second + instance used to yank the log files out from under the first and orphan its + open handles -- which is what made the 2026-08-10 outage unrecoverable. + + flock is used rather than a PID file because it is race-free (no TOCTOU + window between "is that PID alive?" and "claim it") and self-cleaning: the + kernel releases it when the holder dies, however it dies -- including + SIGKILL, which is how a wedged server has to be stopped. + + Returns the open file object; the caller must keep a reference to it for the + process lifetime, since closing it releases the lock. + """ + import fcntl + from pathlib import Path + + Path(log_dir).mkdir(parents=True, exist_ok=True) + lock_path = Path(log_dir) / ".instance.lock" + handle = lock_path.open("w") + try: + fcntl.flock(handle.fileno(), fcntl.LOCK_EX | fcntl.LOCK_NB) + except OSError as exc: + handle.close() + raise InstanceAlreadyRunning( + f"another instance already holds {lock_path}; refusing to start " + f"(starting a second instance would clobber the running one's logs)" + ) from exc + handle.write(f"{os.getpid()}\n") + handle.flush() + return handle diff --git a/integrations/perception-service/src/dlserver/app.py b/integrations/perception-service/src/dlserver/app.py index 642dc6f73..196dd8fa6 100644 --- a/integrations/perception-service/src/dlserver/app.py +++ b/integrations/perception-service/src/dlserver/app.py @@ -15,6 +15,7 @@ import os import secrets import signal +import sys from contextlib import asynccontextmanager from pathlib import Path from typing import Any @@ -47,7 +48,10 @@ set_object_models, set_pose_model, ) +from core.livez import router as livez_router from core.request_context import ( + InstanceAlreadyRunning, + acquire_instance_lock, install_request_id_logging, request_id_middleware, ) @@ -64,6 +68,9 @@ # Must run before any record is emitted: LOG_FORMAT references %(request_id)s. install_request_id_logging() + +# Holds the single-instance flock for the process lifetime; closing it releases. +_instance_lock: object | None = None logger = logging.getLogger(__name__) # --- Auth --- @@ -185,6 +192,8 @@ async def lifespan(app: FastAPI): app = FastAPI(title="DL Backend", lifespan=lifespan) app.middleware("http")(request_id_middleware) +# Liveness: no prefix, no auth. Restricted to localhost at the nginx layer. +app.include_router(livez_router) # Existing perceptions — /hal/api/dl/ prefix app.include_router(action_ws_router, prefix="/hal/api/dl") @@ -223,6 +232,10 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: try: Path(log_dir).mkdir(parents=True, exist_ok=True) + # Hold this for the process lifetime -- see acquire_instance_lock. It must + # be taken BEFORE the rotation below, which renames/unlinks unconditionally. + global _instance_lock + _instance_lock = acquire_instance_lock(log_dir) log_path = Path(log_dir) / "dlserver.log" uvicorn_log_path = Path(log_dir) / "uvicorn.log" # Rotate old logs @@ -262,6 +275,10 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: "uvicorn.access": {"handlers": ["file"], "level": "INFO", "propagate": False}, }, } + except InstanceAlreadyRunning: + # Never fall back to console here: continuing would run a second instance + # that clobbers the live one's log files. Propagate and let main() exit. + raise except Exception as e: logging.basicConfig(level=logging.INFO, format=LOG_FORMAT) logging.getLogger(__name__).warning("File logging setup failed, using console: %s", e) @@ -270,7 +287,11 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: def main() -> None: args = parse_args() - uvicorn_log_config = _setup_logging(args.log_dir) + try: + uvicorn_log_config = _setup_logging(args.log_dir) + except InstanceAlreadyRunning as e: + print(f"refusing to start: {e}", file=sys.stderr) + raise SystemExit(3) from None # Log SIGTERM so we know when the container/orchestrator kills us. # SIGKILL (OOM) can't be caught — but SIGTERM (graceful stop) now logs. diff --git a/integrations/perception-service/src/lbserver/app.py b/integrations/perception-service/src/lbserver/app.py index b1e34dde0..aba5bb8cd 100644 --- a/integrations/perception-service/src/lbserver/app.py +++ b/integrations/perception-service/src/lbserver/app.py @@ -16,6 +16,7 @@ import logging.handlers import os import signal +import sys from contextlib import asynccontextmanager from pathlib import Path from typing import Any @@ -34,7 +35,10 @@ from lbserver.routes.crypto import router as crypto_router from lbserver.utils import RoundRobin from lbserver.utils.crypto import encrypt_http_response, try_decrypt_http_body +from core.livez import router as livez_router from core.request_context import ( + InstanceAlreadyRunning, + acquire_instance_lock, install_request_id_logging, request_id_middleware, ) @@ -44,6 +48,9 @@ # Must run before any record is emitted: LOG_FORMAT references %(request_id)s. install_request_id_logging() + +# Holds the single-instance flock for the process lifetime; closing it releases. +_instance_lock: object | None = None logger = logging.getLogger("lbserver") @@ -84,6 +91,10 @@ async def _lifespan(app: FastAPI): app = FastAPI(title="DL Backend Load Balancer", lifespan=_lifespan) app.middleware("http")(request_id_middleware) app.include_router(crypto_router, prefix="/api/crypto") +# Liveness: no prefix, no auth. MUST be registered before the catch-all +# proxy route below, or /livez would be forwarded to a backend instead of +# answering locally -- which would make lbserver look dead whenever dlserver is. +app.include_router(livez_router) # --------------------------------------------------------------------------- @@ -351,6 +362,10 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: try: Path(log_dir).mkdir(parents=True, exist_ok=True) + # Hold this for the process lifetime -- see acquire_instance_lock. It must + # be taken BEFORE the rotation below, which renames/unlinks unconditionally. + global _instance_lock + _instance_lock = acquire_instance_lock(log_dir) log_path = Path(log_dir) / "lbserver.log" uvicorn_log_path = Path(log_dir) / "uvicorn.log" # Rotate old logs @@ -390,6 +405,10 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: "uvicorn.access": {"handlers": ["file"], "level": "INFO", "propagate": False}, }, } + except InstanceAlreadyRunning: + # Never fall back to console here: continuing would run a second instance + # that clobbers the live one's log files. Propagate and let main() exit. + raise except Exception as e: logging.basicConfig(level=logging.INFO, format=LOG_FORMAT) logging.getLogger(__name__).warning("File logging setup failed, using console: %s", e) @@ -398,7 +417,11 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: def main() -> None: args = parse_args() - uvicorn_log_config = _setup_logging(args.log_dir) + try: + uvicorn_log_config = _setup_logging(args.log_dir) + except InstanceAlreadyRunning as e: + print(f"refusing to start: {e}", file=sys.stderr) + raise SystemExit(3) from None def _handle_sigterm(signum, frame): logger.critical("SIGTERM received — shutting down (pid=%d)", os.getpid()) From 3661b4a4eee5ba6e7b3b60f03ab584ff2eec5ee6 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 14:05:27 +0700 Subject: [PATCH 4/7] fix: recover logging after a failed write instead of dying until restart --- .../docs/troubleshooting.md | 39 ++++++ .../src/core/logging_ext.py | 115 ++++++++++++++++++ .../perception-service/src/dlserver/app.py | 5 +- .../perception-service/src/lbserver/app.py | 5 +- 4 files changed, 160 insertions(+), 4 deletions(-) create mode 100644 integrations/perception-service/src/core/logging_ext.py diff --git a/integrations/perception-service/docs/troubleshooting.md b/integrations/perception-service/docs/troubleshooting.md index 4465d612d..49e8aa72e 100644 --- a/integrations/perception-service/docs/troubleshooting.md +++ b/integrations/perception-service/docs/troubleshooting.md @@ -71,6 +71,45 @@ grep -r "$REQUEST_ID" /var/log/nginx/ /workspace/logs/ || echo "NEVER REACHED TH `urt=` is the upstream response time; compare it against the ladder in [deployment.md](deployment.md#timeout-ladder). +## 1c. A log file stopped growing + +Both servers use `ResilientRotatingFileHandler` (`src/core/logging_ext.py`). The +stock handler never reopens a dead stream, so one failed write silenced a log +until the next restart -- `lbserver.log` stopped at 07:59:35 on 2026-08-17 and +stayed dead for the rest of the day while its mtime kept advancing. + +On a write failure the handler now closes and reopens; if the file itself is +unwritable it rolls over **once** to a fresh inode; if that still fails it mutes +for `retry_after` (30s) and tries again. Failure notices on stderr are +rate-limited to one per window instead of a ~40-line traceback per record. + +So a log that is *permanently* frozen now means the fault outlasted every retry. +Check: + +```bash +# is it really frozen, or just quiet? +stat -c '%s %y' /workspace/logs/lbserver/lbserver.log # sample twice + +# NUL bytes at the tail = the storage lost that region (reads return zeros) +S=$(stat -c %s FILE); N=$(tr -d '\000' < FILE | wc -c); echo "NUL=$((S-N))" + +# read what survives -- less/editors call it binary and garble it +tr -d '\000' < FILE | less + +# is the fd still on a live inode, or a deleted one? +ls -l /proc/$(cat /tmp/lbserver.pid)/fd | grep -a workspace +``` + +| Symptom | Meaning | +|---|---| +| fd shows `(deleted)` | An unlinked-but-open file. Should not happen since the handlers were merged -- if it does, the double-handler bug is back | +| fd on a live inode, NUL tail, size frozen | Storage-side fault on that file's backing chunks. Not preventable from the app; the handler should have rolled over | +| `[logging] write failed` on stderr | The handler is retrying. One line per 30s is normal during a fault | + +> `/workspace` is MooseFS. The client tools that would identify a bad chunk +> (`mfsfileinfo`, `mfscheckfile`) are **not installed** -- worth adding, since +> without them a storage fault can only be inferred from symptoms. + ## 2. Reading the logs Logs are plain text files. No decoding is needed: diff --git a/integrations/perception-service/src/core/logging_ext.py b/integrations/perception-service/src/core/logging_ext.py new file mode 100644 index 000000000..18b48d72e --- /dev/null +++ b/integrations/perception-service/src/core/logging_ext.py @@ -0,0 +1,115 @@ +"""A RotatingFileHandler that survives a failed write. + +The stock handler never reopens a dead stream: once a write raises, that log is +silent until the process restarts. On 2026-08-17 lbserver.log stopped at 07:59:35 +and stayed dead for the rest of the day while its mtime kept advancing -- writes +were still being attempted, still failing, and nothing ever tried again. + +The trigger was storage-side (an EIO on a live, non-deleted file on MooseFS) and +cannot be prevented from here. What can be fixed is the permanence: reopen, and +if the file itself is unwritable, roll over to a fresh one. + +This is filesystem-agnostic on purpose -- it covers a transient ENOSPC on local +disk just as well, which matters on a container whose root is 97% full. +""" + +from __future__ import annotations + +import logging +import sys +import time +from logging.handlers import RotatingFileHandler + + +class ResilientRotatingFileHandler(RotatingFileHandler): + """Reopen on write failure; roll to a fresh file if the current one stays bad. + + Failure handling hangs off handleError() because logging.Handler.emit() + already swallows exceptions and routes them there -- so super().emit() never + raises and cannot be used to detect the fault. + """ + + def __init__( + self, + *args: object, + retry_after: float = 30.0, + failures_before_rollover: int = 3, + **kwargs: object, + ) -> None: + super().__init__(*args, **kwargs) # type: ignore[arg-type] + self.retry_after = retry_after + self.failures_before_rollover = failures_before_rollover + self._consecutive_failures = 0 + self._muted_until = 0.0 + self._last_report = 0.0 + self._errored = False + self._rolled_over_for_fault = False + + def emit(self, record: logging.LogRecord) -> None: + # While muted, drop records rather than retry a known-broken stream for + # every one. Retrying produced ~2 KB/s of tracebacks for 40 minutes in the + # 2026-08-17 incident. + if time.monotonic() < self._muted_until: + return + self._errored = False + super().emit(record) + # Only a write that did NOT route through handleError counts as recovery. + # Checking `self.stream is not None` instead would clear the counter after + # every reopen, so the rollover threshold would never be reached. + if not self._errored and self._consecutive_failures: + self._consecutive_failures = 0 + self._rolled_over_for_fault = False + + def handleError(self, record: logging.LogRecord) -> None: + """Called by Handler.emit() when the write raised. Try to get writable again.""" + self._errored = True + self._consecutive_failures += 1 + self._report(record) + try: + self._close_stream() + if ( + self._consecutive_failures >= self.failures_before_rollover + and not self._rolled_over_for_fault + ): + # Reopening the same path keeps failing if the file itself is the + # problem, so take a fresh inode -- but only once per fault, or a + # persistent fault would churn through every backup and destroy + # the history we are trying to keep. + self.doRollover() + self._rolled_over_for_fault = True + else: + self.stream = self._open() + if self._consecutive_failures >= self.failures_before_rollover: + # A fresh file did not help either; stop trying for a while. + self._muted_until = time.monotonic() + self.retry_after + except Exception: + # Recovery itself failed: back off so we neither spin nor flood. + self._close_stream() + self._muted_until = time.monotonic() + self.retry_after + + def _close_stream(self) -> None: + if self.stream is not None: + try: + self.stream.close() + except Exception: + pass + self.stream = None + + def _report(self, record: logging.LogRecord) -> None: + """Rate-limited failure notice. The stock handler prints a ~40 line + traceback per record, which is the flood this class exists to avoid.""" + if not logging.raiseExceptions or not sys.stderr: + return + now = time.monotonic() + if now - self._last_report < self.retry_after: + return + self._last_report = now + exc = sys.exc_info()[1] + try: + sys.stderr.write( + f"[logging] write failed on {self.baseFilename}: {exc!r} " + f"(failure {self._consecutive_failures}; further notices " + f"suppressed for {self.retry_after:.0f}s)\n" + ) + except Exception: + pass diff --git a/integrations/perception-service/src/dlserver/app.py b/integrations/perception-service/src/dlserver/app.py index 196dd8fa6..c8cdedccf 100644 --- a/integrations/perception-service/src/dlserver/app.py +++ b/integrations/perception-service/src/dlserver/app.py @@ -49,6 +49,7 @@ set_pose_model, ) from core.livez import router as livez_router +from core.logging_ext import ResilientRotatingFileHandler from core.request_context import ( InstanceAlreadyRunning, acquire_instance_lock, @@ -244,7 +245,7 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: bak.unlink() for old in Path(log_dir).glob(f"{prefix}*"): old.rename(Path(str(old) + ".bak")) - handler = logging.handlers.RotatingFileHandler(str(log_path), maxBytes=1_048_576, backupCount=3) + handler = ResilientRotatingFileHandler(str(log_path), maxBytes=1_048_576, backupCount=3) handler.setFormatter(logging.Formatter(LOG_FORMAT)) logging.basicConfig(level=logging.INFO, handlers=[handler]) @@ -263,7 +264,7 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: "handlers": { "file": { "formatter": "default", - "class": "logging.handlers.RotatingFileHandler", + "class": "core.logging_ext.ResilientRotatingFileHandler", "filename": str(uvicorn_log_path), "maxBytes": 1_048_576, "backupCount": 3, diff --git a/integrations/perception-service/src/lbserver/app.py b/integrations/perception-service/src/lbserver/app.py index aba5bb8cd..b302d6406 100644 --- a/integrations/perception-service/src/lbserver/app.py +++ b/integrations/perception-service/src/lbserver/app.py @@ -36,6 +36,7 @@ from lbserver.utils import RoundRobin from lbserver.utils.crypto import encrypt_http_response, try_decrypt_http_body from core.livez import router as livez_router +from core.logging_ext import ResilientRotatingFileHandler from core.request_context import ( InstanceAlreadyRunning, acquire_instance_lock, @@ -374,7 +375,7 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: bak.unlink() for old in Path(log_dir).glob(f"{prefix}*"): old.rename(Path(str(old) + ".bak")) - handler = logging.handlers.RotatingFileHandler(str(log_path), maxBytes=1_048_576, backupCount=3) + handler = ResilientRotatingFileHandler(str(log_path), maxBytes=1_048_576, backupCount=3) handler.setFormatter(logging.Formatter(LOG_FORMAT)) logging.basicConfig(level=logging.INFO, handlers=[handler]) @@ -393,7 +394,7 @@ def _setup_logging(log_dir: str | None) -> dict[str, Any] | None: "handlers": { "file": { "formatter": "default", - "class": "logging.handlers.RotatingFileHandler", + "class": "core.logging_ext.ResilientRotatingFileHandler", "filename": str(uvicorn_log_path), "maxBytes": 1_048_576, "backupCount": 3, From 4e0f9b9385e63fb55ea099c21a2da82d911b70e6 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 14:36:29 +0700 Subject: [PATCH 5/7] fix: reuse one pooled http client instead of building one per request --- .../perception-service/docs/deployment.md | 25 +++++++++- integrations/perception-service/src/config.py | 16 +++++- .../perception-service/src/lbserver/app.py | 50 +++++++++++++++---- 3 files changed, 79 insertions(+), 12 deletions(-) diff --git a/integrations/perception-service/docs/deployment.md b/integrations/perception-service/docs/deployment.md index e00a132fb..cd94a5017 100644 --- a/integrations/perception-service/docs/deployment.md +++ b/integrations/perception-service/docs/deployment.md @@ -264,9 +264,32 @@ layer above it reports an attributable failure rather than inventing its own: | HAL (device) | client read timeout | 10-15s | | nginx | `proxy_read_timeout` (`nginx.conf`) | 45s | | nginx | `proxy_connect_timeout` | 5s | -| lbserver | `lb.http_timeout` (`config.py`) | 30s | +| lbserver | `lb.http_timeout` (`config.py`) — read/write/pool | 30s | +| lbserver | `lb.connect_timeout` | 5s | | lbserver | `lb.ws_open_timeout` | 30s | +### Backend connection pool + +lbserver keeps **one** `httpx.AsyncClient` for the whole process, created in +`lifespan` and closed on shutdown. + +| Setting | Default | Meaning | +|---------|---------|---------| +| `lb.max_connections` | 100 | concurrent connections to all backends | +| `lb.max_keepalive` | 20 | idle connections kept warm | + +It previously built a client **per request**, which re-parsed the CA bundle every +time — about 11 ms of CPU for a plaintext localhost call, capping the LB at +roughly 90 req/s on its single event loop, and opening a fresh TCP connection +that was never reused. Measured: 68 req/s per-request vs 554 req/s pooled, and +1 connection instead of 50 for 50 requests. + +`max_connections` also bounds the damage from a hung backend: once that many +requests are stuck, further ones raise `httpx.PoolTimeout`. That is a +`TimeoutException`, so it surfaces as **504** with the backend named in the log — +the same path as any other backend timeout. Raise it if you see spurious 504s +under healthy load; lower it to fail faster when a backend is sick. + **Never set two adjacent layers to the same value.** nginx and lbserver were both 120s, which made the winner nondeterministic: a hung backend surfaced as `504` sometimes and `500` other times. lbserver must expire first so it can log which diff --git a/integrations/perception-service/src/config.py b/integrations/perception-service/src/config.py index c0f99b747..2bf8bcfde 100644 --- a/integrations/perception-service/src/config.py +++ b/integrations/perception-service/src/config.py @@ -150,9 +150,23 @@ class LBSetting(BaseModel): # before nginx does. Equal timeouts (both were 120s) are a race with a # nondeterministic winner and were why a hung backend surfaced as 504 sometimes # and 500 other times. - http_timeout: float = 30.0 # seconds, httpx client timeout for backend requests + http_timeout: float = 30.0 # seconds, httpx read/write/pool timeout for backend requests + # Connecting to a backend is either instant (localhost) or hopeless. Sharing the + # 30s read budget would make a dead backend take 30s to report instead of ms. + # Mirrors proxy_connect_timeout 5s on nginx. + connect_timeout: float = 5.0 # seconds, httpx connect timeout ws_open_timeout: float = 30.0 # seconds, websocket handshake timeout to backend + # One pooled AsyncClient is shared by every proxied request. Building a client + # per request re-parses the CA bundle each time -- ~11ms of CPU for a plaintext + # localhost call -- which caps the LB at roughly 90 req/s on its single event + # loop. Pooling also stops a failing backend accumulating CLOSE-WAIT sockets + # (433 of them during the 2026-08-17 incident). + # max_connections bounds how many requests a hung backend can tie up; past that + # httpx raises PoolTimeout, which is a TimeoutException and so surfaces as 504. + max_connections: int = 100 + max_keepalive: int = 20 + class Settings(BaseSettings): model_config: ClassVar[SettingsConfigDict] = SettingsConfigDict( diff --git a/integrations/perception-service/src/lbserver/app.py b/integrations/perception-service/src/lbserver/app.py index b302d6406..6a6f014f1 100644 --- a/integrations/perception-service/src/lbserver/app.py +++ b/integrations/perception-service/src/lbserver/app.py @@ -85,8 +85,31 @@ async def _lifespan(app: FastAPI): ) set_crypto(crypto) logger.info("Encryption enabled (key_dir=%s)", settings.crypto.key_dir) - yield - set_crypto(None) + + # One client for the whole process. Created last so an earlier startup failure + # cannot leak it, and closed first on shutdown. + app.state.http_client = httpx.AsyncClient( + timeout=httpx.Timeout( + settings.lb.http_timeout, connect=settings.lb.connect_timeout + ), + limits=httpx.Limits( + max_connections=settings.lb.max_connections, + max_keepalive_connections=settings.lb.max_keepalive, + ), + ) + logger.info( + "HTTP client pool ready (max_connections=%s keepalive=%s timeout=%ss connect=%ss)", + settings.lb.max_connections, + settings.lb.max_keepalive, + settings.lb.http_timeout, + settings.lb.connect_timeout, + ) + try: + yield + finally: + await app.state.http_client.aclose() + app.state.http_client = None + set_crypto(None) app = FastAPI(title="DL Backend Load Balancer", lifespan=_lifespan) @@ -127,15 +150,22 @@ async def proxy_http(request: Request, path: str) -> Response: if request.method in ("POST", "PUT", "PATCH") and body: body, encrypted_key = try_decrypt_http_body(body) + # Reuse the process-wide pooled client. Constructing one per request re-parsed + # the CA bundle every time (~11ms of CPU even for a plaintext localhost call) + # and opened a fresh TCP connection that was never reused. + client: httpx.AsyncClient | None = getattr(request.app.state, "http_client", None) + if client is None: # pragma: no cover - only if lifespan did not run + logger.error("[HTTP] No pooled client; lifespan did not run") + raise HTTPException(status_code=503, detail="Proxy not ready") + try: - async with httpx.AsyncClient(timeout=settings.lb.http_timeout) as client: - resp = await client.request( - method=request.method, - url=url, - headers=headers, - params=dict(request.query_params), - content=body, - ) + resp = await client.request( + method=request.method, + url=url, + headers=headers, + params=dict(request.query_params), + content=body, + ) # Order matters: TimeoutException is a subclass of RequestError, so it must be # caught first. A hung-but-listening backend completes the TCP handshake (the # kernel does it, into the accept queue), so ConnectError never fires and the From c534eff24ba04f30c135bfe796c73581ee688682 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Tue, 18 Aug 2026 15:02:11 +0700 Subject: [PATCH 6/7] fix: stop-tree must not kill a foreign service that holds the port --- .../perception-service/docs/deployment.md | 11 ++++++ .../perception-service/scripts/stop-tree.sh | 34 ++++++++++++++++--- 2 files changed, 41 insertions(+), 4 deletions(-) diff --git a/integrations/perception-service/docs/deployment.md b/integrations/perception-service/docs/deployment.md index cd94a5017..f1b3d275d 100644 --- a/integrations/perception-service/docs/deployment.md +++ b/integrations/perception-service/docs/deployment.md @@ -239,6 +239,17 @@ elsewhere"; liveness failing means "restart this process". 4. **exits non-zero if anything survives**, so `start` refuses to run on a dirty slate rather than dying later on `EADDRINUSE` +It distinguishes two failures, both non-zero: + +| Message | Meaning | +|---------|---------| +| `FAILED to stop cleanly -- our processes survived` | escalation did not work; investigate before retrying | +| `stopped, but port N is still held by another process` | we stopped, but something else owns the port | + +A PID found *only* because it holds the port is checked against the service name +before being killed. On a slave node dlserver binds `LBSERVER_PORT`, so +`stop-runpod-lbserver` would otherwise resolve `:7999` to dlserver and kill it. + A process sharing the caller's own group (an instance from a build predating `setsid`) is killed individually -- killing that group would take down `make` itself mid-stop. diff --git a/integrations/perception-service/scripts/stop-tree.sh b/integrations/perception-service/scripts/stop-tree.sh index 24b4e825c..cf760a50a 100755 --- a/integrations/perception-service/scripts/stop-tree.sh +++ b/integrations/perception-service/scripts/stop-tree.sh @@ -26,9 +26,25 @@ PID_FILE=${4:?} # group covers anything the wrapper spawned (child, size guard, liveness probe); # the port and pid files catch instances started by an older build that predates # setsid. +# A PID found only because it holds PORT must still look like this service. +# On a slave node dlserver binds LBSERVER_PORT, so `stop-runpod-lbserver` would +# otherwise resolve :7999 to dlserver and kill it -- a cross-service kill in the +# one tool people reach for when things are already broken. +owns_port_but_wrong_service() { + local pid=$1 args + args=$(ps -o args= -p "$pid" 2>/dev/null) || return 1 + case "$args" in *"$NAME"*) return 1 ;; esac + echo "[$NAME] pid $pid holds port $PORT but is not $NAME; leaving it alone:" \ + "${args:0:80}" >&2 + return 0 +} + collect() { { - ss -lntpH "sport = :$PORT" 2>/dev/null | grep -oE 'pid=[0-9]+' | cut -d= -f2 + for _p in $(ss -lntpH "sport = :$PORT" 2>/dev/null \ + | grep -oE 'pid=[0-9]+' | cut -d= -f2 | sort -un); do + owns_port_but_wrong_service "$_p" || echo "$_p" + done [[ -r "$WPID_FILE" ]] && cat "$WPID_FILE" [[ -r "$PID_FILE" ]] && cat "$PID_FILE" pgrep -f "run-with-restart.sh .*--log-dir /workspace/logs/$NAME" 2>/dev/null @@ -88,9 +104,19 @@ rm -f "$WPID_FILE" "$PID_FILE" # Verify. Never claim success we have not proven. leftover=$(collect | tr '\n' ' ') -if [[ -n "${leftover// /}" ]] || ss -lntH "sport = :$PORT" 2>/dev/null | grep -q .; then - echo "[$NAME] FAILED to stop cleanly." >&2 - echo "[$NAME] survivors: ${leftover:-none}" >&2 +port_held=$(ss -lntH "sport = :$PORT" 2>/dev/null | grep -c . || true) + +# Two distinct failures, reported differently. Either way exit non-zero: `start` +# is a prerequisite of nothing useful if the port is occupied, whoever holds it. +if [[ -n "${leftover// /}" ]]; then + echo "[$NAME] FAILED to stop cleanly -- our processes survived." >&2 + echo "[$NAME] survivors: $leftover" >&2 + ss -lntp "sport = :$PORT" >&2 2>/dev/null || true + exit 1 +fi +if (( port_held > 0 )); then + echo "[$NAME] stopped, but port $PORT is still held by another process." >&2 + echo "[$NAME] not killed: it is not $NAME. Starting $NAME will fail." >&2 ss -lntp "sport = :$PORT" >&2 2>/dev/null || true exit 1 fi From 8e0ab6951f22e4dcddee09eb9ab906736d80de27 Mon Sep 17 00:00:00 2001 From: loclt1011 Date: Fri, 21 Aug 2026 15:33:45 +0700 Subject: [PATCH 7/7] fix: log the timestamp in the nginx access format --- integrations/perception-service/docs/troubleshooting.md | 9 +++++++++ integrations/perception-service/nginx-ssl.conf | 2 +- integrations/perception-service/nginx.conf | 2 +- 3 files changed, 11 insertions(+), 2 deletions(-) diff --git a/integrations/perception-service/docs/troubleshooting.md b/integrations/perception-service/docs/troubleshooting.md index 49e8aa72e..25d230081 100644 --- a/integrations/perception-service/docs/troubleshooting.md +++ b/integrations/perception-service/docs/troubleshooting.md @@ -71,6 +71,15 @@ grep -r "$REQUEST_ID" /var/log/nginx/ /workspace/logs/ || echo "NEVER REACHED TH `urt=` is the upstream response time; compare it against the ladder in [deployment.md](deployment.md#timeout-ladder). +A full access line carries the timestamp, both status codes, both timings and the +request id -- enough to bound an incident in time without correlating against the +service logs: + +``` +1.2.3.4 [21/Aug/2026:08:15:21 +0000] lelamp-rp.autonomous.ai "POST /api/dl/owlv2 HTTP/1.1" \ + client=200 upstream=200 rt=0.393 urt=0.373 addr=127.0.0.1:7999 rid=79b0250114c29f05 +``` + ## 1c. A log file stopped growing Both servers use `ResilientRotatingFileHandler` (`src/core/logging_ext.py`). The diff --git a/integrations/perception-service/nginx-ssl.conf b/integrations/perception-service/nginx-ssl.conf index 7d4f94486..fd0d4e384 100644 --- a/integrations/perception-service/nginx-ssl.conf +++ b/integrations/perception-service/nginx-ssl.conf @@ -19,7 +19,7 @@ http { # client=502 upstream=- backend down (connect refused) # no line at all never reached this box (Cloudflare / ingress / caller) log_format upstream_detail - '$remote_addr $host "$request" ' + '$remote_addr [$time_local] $host "$request" ' 'client=$status upstream=$upstream_status ' 'rt=$request_time urt=$upstream_response_time ' 'addr=$upstream_addr rid=$req_id "$http_user_agent"'; diff --git a/integrations/perception-service/nginx.conf b/integrations/perception-service/nginx.conf index 59bc03b64..80cb733f9 100644 --- a/integrations/perception-service/nginx.conf +++ b/integrations/perception-service/nginx.conf @@ -19,7 +19,7 @@ http { # client=502 upstream=- backend down (connect refused) # no line at all never reached this box (Cloudflare / ingress / caller) log_format upstream_detail - '$remote_addr $host "$request" ' + '$remote_addr [$time_local] $host "$request" ' 'client=$status upstream=$upstream_status ' 'rt=$request_time urt=$upstream_response_time ' 'addr=$upstream_addr rid=$req_id "$http_user_agent"';