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).
This commit is contained in:
maziggy
2026-07-11 14:44:45 +02:00
parent aba00598bb
commit ba1394db3e
8 changed files with 202 additions and 7 deletions
+2
View File
@@ -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
+15 -1
View File
@@ -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}"]
@@ -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", "<!--"))
]
class TestDockerImage:
def test_cmd_execs_uvicorn_so_it_becomes_pid_1(self):
"""Without exec, `sh` is PID 1, dash eats the SIGTERM, and docker stop
always ends in SIGKILL after the grace period.
"""
cmd = next(line for line in _read("Dockerfile").splitlines() if line.startswith("CMD "))
assert "exec uvicorn" in cmd, (
"Dockerfile CMD must `exec` uvicorn. Without it the shell stays as PID 1, "
"uvicorn never receives SIGTERM, and every docker stop is a SIGKILL:\n" + cmd
)
def test_cmd_bounds_the_graceful_shutdown(self):
cmd = next(line for line in _read("Dockerfile").splitlines() if line.startswith("CMD "))
assert FLAG in cmd, cmd
def test_compose_allows_more_than_dockers_default_grace(self):
compose = _read("docker-compose.yml")
assert "stop_grace_period:" in compose, (
"docker-compose.yml should raise stop_grace_period above Docker's 10s default, "
"so a slow teardown on a Pi is not clipped by a SIGKILL."
)
class TestSystemdUnits:
@pytest.mark.parametrize("unit", ["deploy/bambuddy.service"])
def test_execstart_bounds_the_graceful_shutdown(self, unit):
exec_start = next(line for line in _read(unit).splitlines() if line.startswith("ExecStart="))
assert FLAG in exec_start, exec_start
@pytest.mark.parametrize("unit", ["deploy/bambuddy.service"])
def test_stop_timeout_leaves_room_for_the_teardown(self, unit):
"""systemd's timer is the backstop, not the mechanism — but it still has
to outlast uvicorn's own 5s wait plus the app's ~1-2s of teardown.
"""
match = re.search(r"^TimeoutStopSec=(\d+)", _read(unit), re.M)
assert match, "unit should state a TimeoutStopSec rather than inherit the 90s default"
assert int(match.group(1)) >= 15, (
f"TimeoutStopSec={match.group(1)}s can clip the teardown: uvicorn waits up to 5s "
"for in-flight requests, then the app checkpoints the WAL and stops the virtual "
"printers."
)
class TestInstallScript:
def test_generated_systemd_unit_bounds_the_shutdown(self):
lines = _uvicorn_lines(_read("install/install.sh"))
exec_start = [line for line in lines if line.startswith("ExecStart=")]
assert exec_start, "install.sh no longer emits a systemd ExecStart line"
for line in exec_start:
assert FLAG in line, line
def test_generated_launchd_plist_bounds_the_shutdown(self):
"""The macOS plist passes argv as a <string> array, so the flag and its
value are two separate entries.
"""
plist_region = _read("install/install.sh")
assert f"<string>{FLAG}</string>" in plist_region, (
"the launchd plist in install.sh does not pass --timeout-graceful-shutdown"
)
class TestWindowsService:
def test_nssm_registration_bounds_the_shutdown(self):
bat = _read("installers/windows/service/install-service.bat")
install_line = next(line for line in _uvicorn_lines(bat) if "install Bambuddy" in line)
assert FLAG in install_line, install_line
def test_nssm_waits_long_enough_for_the_ctrl_c_stop(self):
"""NSSM's default AppStopMethodConsole is 1500ms. Uvicorn shuts down on
the Ctrl-C but needs longer than that, so Windows was force-killing it
mid-teardown.
"""
bat = _read("installers/windows/service/install-service.bat")
match = re.search(r"AppStopMethodConsole\s+(\d+)", bat)
assert match, "install-service.bat must raise NSSM's 1500ms console-stop default"
assert int(match.group(1)) >= 10000, match.group(1)
+13 -3
View File
@@ -34,14 +34,24 @@ Environment="PATH=INSTALL_PATH/venv/bin:/usr/local/bin:/usr/bin:/bin"
# Server configuration
# --loop asyncio is required: uvloop's SSL layer can silently truncate VP FTP
# uploads on a ragged client close over slow storage (#1896). Do not remove.
ExecStart=INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host 0.0.0.0 --port ${PORT:-8000} --loop asyncio
#
# --timeout-graceful-shutdown is also required. Uvicorn's default is to wait
# forever for in-flight requests, and an MJPEG camera stream is a response that
# never completes — one open camera tile would hang the stop until systemd gave
# up and SIGKILLed, skipping the WAL checkpoint, the MQTT disconnect and the
# virtual-printer teardown entirely. On timeout uvicorn cancels the request
# tasks; the camera generators unwind cleanly on CancelledError.
ExecStart=INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host 0.0.0.0 --port ${PORT:-8000} --loop asyncio --timeout-graceful-shutdown 5
# Restart policy
Restart=on-failure
RestartSec=5
# Graceful shutdown
TimeoutStopSec=10
# Graceful shutdown. Uvicorn now bounds its own wait at 5s and the app's own
# teardown takes ~1-2s, so this only has to be comfortably longer than that —
# it is the backstop, not the mechanism. The old 10s could clip a slow teardown
# on a Pi with several virtual printers.
TimeoutStopSec=30
# Kill zombie ffmpeg processes (timelapse processing)
ExecStartPre=-/usr/bin/pkill -9 -f "ffmpeg.*bambuddy"
+7
View File
@@ -147,6 +147,13 @@ services:
# You also need to mount your certificates to the container (see volumes section above).
# - USE_SYSTEM_TRUST_STORE=true
restart: unless-stopped
# Docker's default is 10s, after which it SIGKILLs. Bambuddy shuts down in
# well under that (uvicorn caps its wait on in-flight requests at 5s, then
# the app checkpoints the SQLite WAL, disconnects MQTT and stops the virtual
# printers), but a Pi with several virtual printers and a slow SD card can be
# nearer the limit than is comfortable. The headroom costs nothing — the
# container exits as soon as it is done, not when the timer expires.
stop_grace_period: 30s
# Optional: External PostgreSQL database
# Uncomment to run Postgres alongside Bambuddy (or use an external Postgres host)
+12 -1
View File
@@ -592,9 +592,15 @@ Environment="LOG_DIR=$LOG_DIR"
Environment="TZ=$TIMEZONE"
# --loop asyncio required: uvloop can truncate VP FTP uploads (#1896)
ExecStart=$INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host $BIND_ADDRESS --port $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.
ExecStart=$INSTALL_PATH/venv/bin/uvicorn backend.app.main:app --host $BIND_ADDRESS --port $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
@@ -660,6 +666,11 @@ create_launchd_service() {
<!-- the loop asyncio flag below is required: uvloop can truncate VP FTP uploads, #1896 -->
<string>--loop</string>
<string>asyncio</string>
<!-- required: uvicorn otherwise waits forever for in-flight requests, and an
MJPEG camera stream never completes — one open camera tile hangs the stop
until launchd SIGKILLs, skipping the WAL checkpoint and MQTT teardown -->
<string>--timeout-graceful-shutdown</string>
<string>5</string>
</array>
<key>WorkingDirectory</key>
<string>$INSTALL_PATH</string>
+18 -1
View File
@@ -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.
+8 -1
View File
@@ -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