From ba1394db3e797fa6576c21b49832a50346afffda Mon Sep 17 00:00:00 2001 From: maziggy Date: Sat, 11 Jul 2026 14:44:45 +0200 Subject: [PATCH] fix(shutdown): exec uvicorn as PID 1 in Docker, and bound the graceful-shutdown wait Two defects, both invisible until you ask the app to stop. Docker never shut down gracefully at all. CMD ["sh","-c","uvicorn ..."] left the shell as PID 1 with uvicorn as its child, and dash does not forward signals, so docker stop SIGTERMed the shell and uvicorn never heard about it. Measured on the shipped image: the full 10s grace period, exit 137, and no "Shutting down" line in the log. Every stop, restart and image update was a hard kill -- no WAL checkpoint, no MQTT disconnect, no virtual-printer teardown. `exec` makes uvicorn PID 1; the rebuilt image now stops in 1s with exit 0 and checkpoints the WAL. Separately, uvicorn's timeout_graceful_shutdown defaults to None -- wait forever for in-flight requests. An MJPEG camera stream is a response that never completes (httptools' connection shutdown() only flips keep_alive on an in-flight cycle, it never closes the transport), so one open camera tile pinned the process until systemd SIGKILLed at 90s. The ordering makes it unfixable from inside the app: uvicorn fires the lifespan shutdown -- the code that tears the streams down -- only after connections drain. All six launchers now pass --timeout-graceful-shutdown 5: Dockerfile, deploy/bambuddy.service, the systemd unit and launchd plist from install/install.sh, the SpoolBuddy installer's unit, and the Windows NSSM registration. On timeout uvicorn cancels the request tasks; the camera generators already unwind cleanly on CancelledError. TimeoutStopSec raised to 30s on the units and stop_grace_period: 30s added to compose, as backstops rather than the mechanism. On Windows NSSM's default 1500ms AppStopMethodConsole was force-killing uvicorn mid-teardown; raised to 15s, with the WM_CLOSE and thread-message stages skipped (uvicorn is a console app with neither a window nor a message loop). --- CHANGELOG.md | 2 + Dockerfile | 16 ++- .../unit/test_launcher_shutdown_config.py | 127 ++++++++++++++++++ deploy/bambuddy.service | 16 ++- docker-compose.yml | 7 + install/install.sh | 13 +- .../windows/service/install-service.bat | 19 ++- spoolbuddy/install/install.sh | 9 +- 8 files changed, 202 insertions(+), 7 deletions(-) create mode 100644 backend/tests/unit/test_launcher_shutdown_config.py diff --git a/CHANGELOG.md b/CHANGELOG.md index de2b0a722..66def6bf8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ All notable changes to Bambuddy will be documented in this file. ## [0.2.5b2] - Unreleased ### Fixed +- **Docker never shut down gracefully — every stop, restart and update was a SIGKILL** — `CMD ["sh", "-c", "uvicorn ..."]` left the shell as PID 1 with uvicorn as its child, and dash does not forward signals. So `docker stop` SIGTERMed the shell and **uvicorn never heard about it**. Measured on the shipped image: the stop ran the full 10-second grace period, the container exited **137** (SIGKILL), and the log contained no "Shutting down" line at all — it simply stopped dead after `Uvicorn running on ...`. That means the entire shutdown path had never once executed in Docker: no SQLite WAL checkpoint, no MQTT disconnect (the broker saw an ungraceful drop every time), no virtual-printer teardown, no printer disconnect, no `engine.dispose()`. Not "when a camera is streaming" — *always*, on every `docker stop`, `docker restart`, `compose down` and image update. The fix is one word: `CMD ["sh", "-c", "exec uvicorn ..."]`. With `exec`, uvicorn *is* PID 1 and receives the signal. Verified on a rebuilt image: PID 1 is now `uvicorn`, `docker stop` completes in **1 second** with **exit code 0**, and the log shows `Shutting down` → `WAL checkpoint completed` → `Application shutdown complete`. +- **`systemctl restart` could hang for 90 seconds and end in SIGKILL** — with a camera tile open, stopping Bambuddy would sit at `Waiting for connections to close.` until systemd gave up and killed it. Uvicorn's `timeout_graceful_shutdown` defaults to `None`, i.e. **wait forever** for in-flight requests, and an MJPEG camera stream is a response that never completes — `httptools`'s connection `shutdown()` only flips `keep_alive = False` on an in-flight cycle, it never closes the transport. So a single open stream pinned the process. Worse, the ordering is inverted: uvicorn only fires the **lifespan shutdown** — the code that would tear those streams down — *after* the connections drain, so the cleanup that would unblock the wait was itself blocked by the wait. Every launcher now passes `--timeout-graceful-shutdown 5`: the Dockerfile, the shipped `deploy/bambuddy.service`, the systemd unit and launchd plist emitted by `install/install.sh`, the SpoolBuddy installer's unit (a kiosk parked on the printers page holds exactly such a stream open, so this bit it on every reboot), and the Windows NSSM registration. On timeout uvicorn cancels the request tasks and the camera generators unwind cleanly on `CancelledError` — a path they already handled. `TimeoutStopSec` is raised to 30s on the systemd units as a backstop rather than the mechanism, and `stop_grace_period: 30s` added to the compose file so a slow teardown on a Pi isn't clipped. On Windows, NSSM's stop sequence was also force-killing uvicorn mid-teardown: its default `AppStopMethodConsole` is **1500 ms**, far less than uvicorn needs, so that is raised to 15s and the useless WM_CLOSE / thread-message stages (uvicorn is a console app with no window and no message loop) are skipped. **Tests.** 9 cases pinning every launcher — that the Dockerfile `exec`s, that each of the six launch points carries the timeout flag, that the systemd stop timeouts leave room for the teardown, and that NSSM waits long enough for the Ctrl-C. None of this shows up in a functional test: the app is perfectly healthy right up until you ask it to stop. - **Energy Summary stuck at zero for Yesterday and Total on REST smart plugs — and the Statistics energy figure with it (#2539, reporter @R3play210)** — A Shelly Plug S Gen3 wired up over the REST integration showed live power and a Today figure that climbed, but Yesterday and Total never moved off zero, through five days of printing. **The bug.** `RESTSmartPlugService.get_energy()` returned a dict with two keys, `power` and `today`. It never set `yesterday` or `total` at all, so `SmartPlugEnergy` defaulted them to null and the summary card summed nothing. Tasmota returns all three; Home Assistant returns two; REST returned one. **The number that looked right was also wrong.** A Shelly has no notion of "today" — its only energy figure is `aenergy.total`, a lifetime counter in watt-hours that climbs forever and never resets. Bambuddy had a single energy field, so the reporter put the lifetime counter in it, and line 230 filed it under `today`. It *looked* correct because it grows; it just never dropped back to zero at midnight. The one figure he trusted was the least trustworthy of the four. **It broke more than the card.** With `total` never populated, the hourly snapshot recorder skipped the plug outright (its own comment said so: *"REST plugs that only expose today can't be used for cumulative snapshots"*), `_sum_live_plug_totals()` summed zero, and since the reporter's `energy_tracking_mode` is `total`, the **Statistics page's energy figure was zero too** — he simply hadn't got to it yet. **The fix.** A REST plug now says which counter it has: `rest_energy_path` still means "energy used today", and a new `rest_energy_total_path` means "lifetime counter that never resets". A Shelly has only the latter; a Tasmota behind a REST bridge has both; both are read from one HTTP fetch when they share a URL. Then, because the snapshot table already records that lifetime counter hourly, **Today and Yesterday are derived from it**: today = the counter now minus its value at the last local midnight, yesterday = that midnight's value minus the one before. So a Shelly gets all four numbers with no new device capability — and Home Assistant's permanently-null Yesterday is fixed for free. Today appears after the first midnight the install lives through, Yesterday after the second; a counter that goes backwards (factory reset zeroes `aenergy.total`) reports nothing rather than a negative. **Local midnight, not UTC.** With `TZ=Europe/Berlin` a UTC boundary would roll Today over at 02:00 wall-clock. The snapshot loop now ticks on the *local* hour instead of every 3600s from boot, so a reading lands exactly on the day boundary — including in the half-hour-offset zones (India, Nepal) where local midnight isn't on a UTC hour at all. Previously the last snapshot before midnight could be up to an hour early, and an hour of a printer's draw is real watt-hours to lose off the day. **Collateral: the whole smart-plug subsystem was broken on Postgres.** Every `DateTime` column in the smart-plug tables is naive and holds UTC, but the code wrote *aware* datetimes into them. SQLite tolerates that — its bind processor reads the fields and drops the offset — which is why it went unnoticed. asyncpg does not: it raises `DataError: invalid input for query argument`. So on Postgres every energy-snapshot capture raised (silently, inside the loop's `except`), leaving the snapshot table empty and the date-filtered energy stat permanently zero, and every plug status poll raised on `last_checked`. Postgres is what Bambuddy recommends for multi-printer installs, so this was not a corner. All smart-plug timestamps are now naive UTC via a shared `utcnow_naive()` / `to_naive_utc()`, and the snapshot-delta query normalises its bounds the same way. **Tests.** 8 cases on the derivation (today and yesterday from the counter; yesterday absent until two midnights have passed; nothing derivable before the first; a counter reset reports nothing rather than a negative; another plug's snapshots are not borrowed; a device-reported figure is never overwritten by our arithmetic). 4 on the REST driver, using the reporter's own `Switch.GetStatus` payload (the lifetime counter lands in `total` and *not* in `today`; a plug reporting both keeps them apart; a total path alone is enough to read energy at all; both counters share one HTTP fetch). 4 more pin the Postgres-unsafe datetime — mutation-verified: reintroducing the aware timestamp fails the guard. Migration applied and re-applied against a real Postgres to confirm it is idempotent and defaults to NULL. **Existing REST users:** if your Energy JSON Path points at a cumulative counter (anything from a Shelly does), move it to the new **Energy JSON Path (lifetime)** field — the form and the wiki now say which field wants which counter. ### Added diff --git a/Dockerfile b/Dockerfile index b9d270fdd..e1f089df5 100644 --- a/Dockerfile +++ b/Dockerfile @@ -150,5 +150,19 @@ HEALTHCHECK --interval=30s --timeout=10s --start-period=10s --retries=3 \ # Port is configurable via PORT (default 8000); bind address via HOST (default # 0.0.0.0). Set HOST=127.0.0.1 to bind loopback only, e.g. when a reverse proxy # on the same host fronts the app. +# +# `exec` is load-bearing, not style. Without it the shell stays as PID 1 and +# uvicorn runs as its child; dash does not forward signals, so `docker stop` +# SIGTERMs the shell and uvicorn never hears about it. Every stop then ran to +# the end of the grace period and died on SIGKILL (exit 137) — no WAL +# checkpoint, no MQTT disconnect, no virtual-printer teardown, on every restart +# and every image update. With `exec`, uvicorn *is* PID 1 and gets the signal. +# +# --timeout-graceful-shutdown caps the wait on in-flight requests. Uvicorn's +# default is to wait forever, and an MJPEG camera stream is a response that +# never completes, so a single open camera tile would otherwise pin the process +# past Docker's 10s grace and back into SIGKILL. On timeout uvicorn cancels the +# request tasks; the camera generators already unwind cleanly on CancelledError. +ENV UVICORN_TIMEOUT_GRACEFUL_SHUTDOWN=5 ENTRYPOINT ["/usr/local/bin/docker-entrypoint.sh"] -CMD ["sh", "-c", "uvicorn backend.app.main:app --host ${HOST:-0.0.0.0} --port ${PORT:-8000} --loop asyncio"] +CMD ["sh", "-c", "exec uvicorn backend.app.main:app --host ${HOST:-0.0.0.0} --port ${PORT:-8000} --loop asyncio --timeout-graceful-shutdown ${UVICORN_TIMEOUT_GRACEFUL_SHUTDOWN}"] diff --git a/backend/tests/unit/test_launcher_shutdown_config.py b/backend/tests/unit/test_launcher_shutdown_config.py new file mode 100644 index 000000000..9ec479b24 --- /dev/null +++ b/backend/tests/unit/test_launcher_shutdown_config.py @@ -0,0 +1,127 @@ +"""Every launcher must be able to shut Bambuddy down gracefully. + +Two defects, found together, both invisible until you look for them: + +1. **The Docker image never received SIGTERM at all.** ``CMD ["sh", "-c", + "uvicorn ..."]`` leaves the shell as PID 1 with uvicorn as its child, and + dash does not forward signals. Measured on the shipped image: ``docker stop`` + ran the full 10s grace period, exited 137 (SIGKILL), and the container log + contained no "Shutting down" line. So *every* stop, restart and image update + was a hard kill — no WAL checkpoint, no MQTT disconnect, no virtual-printer + teardown. ``exec`` makes uvicorn PID 1 and the signal lands. + +2. **Uvicorn waits forever for in-flight requests.** + ``timeout_graceful_shutdown`` defaults to None, and an MJPEG camera stream is + a response that never completes — ``httptools``'s connection ``shutdown()`` + only flips ``keep_alive = False`` on an in-flight cycle, it does not close the + transport. One open camera tile pins the process indefinitely, and the app's + own teardown never runs because uvicorn only fires the lifespan shutdown + *after* connections drain. The flag caps the wait and cancels the tasks; the + camera generators already unwind cleanly on CancelledError. + +Neither shows up in any functional test — the app is perfectly healthy right up +until you ask it to stop. Hence this: pin the launchers themselves. +""" + +from __future__ import annotations + +import re +from pathlib import Path + +import pytest + +REPO = Path(__file__).resolve().parents[3] + +FLAG = "--timeout-graceful-shutdown" + + +def _read(rel: str) -> str: + path = REPO / rel + assert path.is_file(), f"launcher moved or was removed: {rel}" + return path.read_text() + + +def _uvicorn_lines(text: str) -> list[str]: + """Lines that actually launch uvicorn, ignoring comments about it.""" + return [ + line for line in text.splitlines() if "uvicorn" in line and not line.lstrip().startswith(("#", "REM", " --loop asyncio + + --timeout-graceful-shutdown + 5 WorkingDirectory $INSTALL_PATH diff --git a/installers/windows/service/install-service.bat b/installers/windows/service/install-service.bat index 5d8e5b35e..98969029e 100644 --- a/installers/windows/service/install-service.bat +++ b/installers/windows/service/install-service.bat @@ -30,7 +30,11 @@ REM "service not found" returns non-zero and we want to proceed. REM Register the service. NSSM wraps uvicorn so Windows treats it as a REM proper service (autostart, recovery, supervised restart). REM --loop asyncio required: uvloop can truncate VP FTP uploads (#1896). -"%NSSM%" install Bambuddy "%PYTHON%" "-m uvicorn backend.app.main:app --host 0.0.0.0 --port %PORT% --loop asyncio" +REM --timeout-graceful-shutdown required: uvicorn otherwise waits forever for +REM in-flight requests, and an MJPEG camera stream is a response that never +REM completes — one open camera tile hangs the stop until NSSM force-kills, +REM skipping the WAL checkpoint and the MQTT / virtual-printer teardown. +"%NSSM%" install Bambuddy "%PYTHON%" "-m uvicorn backend.app.main:app --host 0.0.0.0 --port %PORT% --loop asyncio --timeout-graceful-shutdown 5" if errorlevel 1 ( echo [install-service] nssm install failed exit /b 1 @@ -42,6 +46,19 @@ REM Service configuration "%NSSM%" set Bambuddy Description "Bambuddy — local-first Bambu Lab printer manager" "%NSSM%" set Bambuddy Start SERVICE_AUTO_START +REM Shutdown behaviour. NSSM's stop sequence is Ctrl-C, then WM_CLOSE, then a +REM thread message, then TerminateProcess — each with a 1500 ms default wait. +REM Uvicorn shuts down on the Ctrl-C, but needs longer than 1.5 seconds to +REM finish: it drains in-flight requests (bounded at 5s by the flag above) and +REM then runs the app teardown — WAL checkpoint, MQTT disconnect, virtual- +REM printer stop. At the default timeout Windows force-killed it mid-teardown. +REM +REM Skip=6 drops the WM_CLOSE (2) and thread-message (4) methods: uvicorn is a +REM console app with no window and no message loop, so both were only burning +REM another 3 seconds before the kill. Ctrl-C is the one that works. +"%NSSM%" set Bambuddy AppStopMethodSkip 6 +"%NSSM%" set Bambuddy AppStopMethodConsole 15000 + REM Environment: point DATA_DIR + LOG_DIR at ProgramData, prepend our REM bin/ to PATH so ffmpeg/ffprobe are found by the shutil.which() lookup REM in backend/app/services/layer_timelapse.py. diff --git a/spoolbuddy/install/install.sh b/spoolbuddy/install/install.sh index a69b230ba..18cb764ba 100755 --- a/spoolbuddy/install/install.sh +++ b/spoolbuddy/install/install.sh @@ -771,9 +771,16 @@ EnvironmentFile=$INSTALL_PATH/.env Environment="DATA_DIR=$INSTALL_PATH/data" Environment="LOG_DIR=$INSTALL_PATH/logs" # --loop asyncio required: uvloop can truncate VP FTP uploads (#1896) -ExecStart=$INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host 0.0.0.0 --port $BAMBUDDY_PORT --loop asyncio +# --timeout-graceful-shutdown required: uvicorn otherwise waits forever for +# in-flight requests, and an MJPEG camera stream never completes — one open +# camera tile hangs the stop until systemd SIGKILLs, skipping the WAL +# checkpoint and the MQTT / virtual-printer teardown. A kiosk sitting on the +# printers page holds exactly such a stream open, so this bites every reboot. +ExecStart=$INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host 0.0.0.0 --port $BAMBUDDY_PORT --loop asyncio --timeout-graceful-shutdown 5 Restart=on-failure RestartSec=5 +# Backstop only — uvicorn bounds its own wait at 5s and teardown takes ~1-2s. +TimeoutStopSec=30 StandardOutput=journal StandardError=journal