From 79bfe2a89b8c2ee1c3d2627937820f79076ec66a Mon Sep 17 00:00:00 2001 From: Ryan Malloy Date: Mon, 2 Mar 2026 18:28:04 -0700 Subject: [PATCH] Fix sequential timeout stacking in shutdown budget MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The same shutdown_timeout was used for both uvicorn handler drain AND queue.stop() consumer drain — sequential phases sharing Docker's wall-clock budget. With 30s each, worst case was 60s, exceeding the 35s stop_grace_period and causing SIGKILL. Fix: uvicorn gets a fixed 3s drain (handlers just re-raise), queue gets the full shutdown_timeout. Docker grace = 3 + timeout + 5s safety. Also adds shutdown observability: startup logs the timing chain, queue.stop() logs remaining audio vs available budget. --- CLAUDE.md | 9 +++++++-- docker-compose.yml | 4 +++- src/tts_mcp/__main__.py | 13 +++++++++---- src/tts_mcp/queue.py | 14 +++++++++++++- src/tts_mcp/server.py | 4 ++++ 5 files changed, 36 insertions(+), 8 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index b1e42aa..9a9ab05 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -122,7 +122,12 @@ When a currently-playing item is explicitly cancelled, pw-play is killed immedia On `docker compose down` or `make restart`, the server lets the currently-playing speech finish before stopping — no more mid-sentence cutoffs. -**How it works:** `queue.stop()` sets a flag and waits up to `shutdown_timeout` seconds for the consumer to finish the current item. If the timeout expires, it falls back to hard cancel. Docker's `stop_grace_period: 35s` gives the 30s shutdown timeout room to complete before SIGKILL. +**How it works:** SIGTERM triggers a two-phase shutdown that shares Docker's wall-clock budget: + +1. **Phase 1 — Handler drain (3s fixed):** Uvicorn cancels in-flight `speak()` handlers. The handlers re-raise `CancelledError` without touching the consumer — audio keeps playing. +2. **Phase 2 — Queue drain (`shutdown_timeout`, default 30s):** Lifespan finalizer calls `queue.stop()`, which waits for the consumer to finish the current audio. If the timeout expires, it force-cancels. + +Docker's `stop_grace_period` must exceed the total: `3s + shutdown_timeout + 5s safety margin` (default 38s). If the max expected audio length exceeds `shutdown_timeout`, increase both `TTS_SHUTDOWN_TIMEOUT` and `stop_grace_period`. **Entry tone timing:** The Nextel chirp fires immediately when `speak()` is called (before synthesis), acting as an audible "I heard you" that covers the 1-3s synthesis latency. Exit/standby tones still play from the consumer (they depend on queue state after playback). @@ -135,7 +140,7 @@ On `docker compose down` or `make restart`, the server lets the currently-playin - Explicit `cancel_speech()` kills pw-play + plays cancel tone; MCP disconnect lets playback finish - Consumer directly awaits `play_audio()`; `cancel()` targets the consumer task with `_item_cancelled` flag - `speak()`'s CancelledError handler does NOT cancel the consumer — only explicit cancel does -- Graceful shutdown: uvicorn waits `shutdown_timeout` for handlers, consumer finishes audio naturally, then lifespan runs `queue.stop()` +- Graceful shutdown is two-phase: 3s handler drain (fixed) + `shutdown_timeout` queue drain, both sequential within Docker's `stop_grace_period` - Tones are non-fatal: if `pw-play` fails on a tone, speech still plays - Orpheus uses llama-server (not Ollama) for 15x throughput via continuous batching - SNAC decoder is lazy-loaded on first Orpheus call to reduce idle memory diff --git a/docker-compose.yml b/docker-compose.yml index e65e61e..eb08952 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -3,7 +3,9 @@ services: build: . container_name: tts-mcp restart: unless-stopped - stop_grace_period: 35s + # Must exceed: 3s handler drain + TTS_SHUTDOWN_TIMEOUT + 5s safety margin. + # Default: 3 + 30 + 5 = 38s. Increase if TTS_SHUTDOWN_TIMEOUT > 30. + stop_grace_period: 38s env_file: .env environment: # Override for Docker networking (container DNS instead of IPs) diff --git a/src/tts_mcp/__main__.py b/src/tts_mcp/__main__.py index a9dab94..4b03dba 100644 --- a/src/tts_mcp/__main__.py +++ b/src/tts_mcp/__main__.py @@ -10,10 +10,15 @@ def main(): host=settings.host, port=settings.port, stateless_http=True, - # Override FastMCP's default timeout_graceful_shutdown=0 so uvicorn - # lets in-flight speak() calls finish before cancelling them. Must - # be shorter than Docker's stop_grace_period (35s) to avoid SIGKILL. - uvicorn_config={"timeout_graceful_shutdown": settings.shutdown_timeout}, + # On SIGTERM, uvicorn drains HTTP handlers first (Phase 1), then runs + # lifespan shutdown where queue.stop() waits for the consumer (Phase 2). + # These phases are SEQUENTIAL and share Docker's stop_grace_period budget. + # + # Phase 1 (handler drain): 3s — speak() just re-raises CancelledError, + # it does not cancel the consumer (audio keeps playing). + # Phase 2 (queue.stop): shutdown_timeout — consumer finishes current audio. + # Docker budget: shutdown_timeout + 3s handler drain + 5s safety margin. + uvicorn_config={"timeout_graceful_shutdown": 3}, ) diff --git a/src/tts_mcp/queue.py b/src/tts_mcp/queue.py index 62af471..4ccdf3e 100644 --- a/src/tts_mcp/queue.py +++ b/src/tts_mcp/queue.py @@ -138,6 +138,18 @@ class SpeechQueue: self._stopped = True try: if self._consumer_task and not self._consumer_task.done(): + # Log what we're waiting for + if self._current: + elapsed = time.time() - self._current.enqueued_at + remaining = max(0, self._current.result.duration_seconds - elapsed) + print( + f"Speech queue: waiting for current audio " + f"(~{remaining:.0f}s remaining, budget {self._shutdown_timeout:.0f}s)", + file=sys.stderr, + ) + else: + print("Speech queue: consumer idle, shutting down", file=sys.stderr) + # Consumer polls _stopped every 0.5s between items, so it will # exit the while loop after finishing the current item. try: @@ -151,7 +163,7 @@ class SpeechQueue: ) except asyncio.TimeoutError: print( - f"Speech queue: shutdown timeout ({self._shutdown_timeout}s) " + f"Speech queue: shutdown timeout ({self._shutdown_timeout:.0f}s) " f"expired, force-cancelling consumer", file=sys.stderr, ) diff --git a/src/tts_mcp/server.py b/src/tts_mcp/server.py index 8121d8b..fd66584 100644 --- a/src/tts_mcp/server.py +++ b/src/tts_mcp/server.py @@ -88,6 +88,10 @@ async def app_lifespan(server: FastMCP): f" Voice identity: {identity_label}{announce_label}", file=sys.stderr, ) + print( + f" Shutdown budget: 3s handler drain + {settings.shutdown_timeout:.0f}s queue drain + 5s safety", + file=sys.stderr, + ) try: yield {