Apagar dentro del tiempo que systemd concede

cogs/music.py

@@ -15,6 +15,12 @@
 # Query length cap — guards against absurd input before it reaches yt-dlp.
 MAX_QUERY_LEN = 500
 
+# How long to wait for a voice connection. discord.py reuses this same value as
+# the deadline for Discord to confirm a *departure* while closing, so it is also
+# the worst case a shutdown can take — it must stay under the unit's
+# TimeoutStopSec or systemd kills the process mid-teardown. See issue #35.
+VOICE_CONNECT_TIMEOUT = 20.0
+
 
 def _is_playlist_url(query: str) -> bool:
     """Detect playlist/set/album URLs across supported sites."""
@@ -44,7 +50,7 @@ async def _ensure_voice(self, ctx) -> bool:
         vc = ctx.voice_client
         try:
             if vc is None:
-                await dest.connect(timeout=20, reconnect=True)
+                await dest.connect(timeout=VOICE_CONNECT_TIMEOUT, reconnect=True)
             elif vc.channel != dest:
                 await vc.move_to(dest)
             return True

deploy/install-units.sh

@@ -43,7 +43,13 @@ Restart=on-failure
 RestartSec=5
 # Give the bot a moment to shut down cleanly.
 KillSignal=SIGINT
-TimeoutStopSec=15
+# Must stay above cogs.music.VOICE_CONNECT_TIMEOUT. discord.py reuses the voice
+# *connect* timeout as the deadline for Discord to confirm a departure, and
+# Client.close() waits that out for every voice client. With 15s here and 20s
+# there, systemd SIGKILLed a shutdown that was going to finish — which skipped
+# the reaping of FFmpeg and yt-dlp. A clean stop still takes milliseconds; this
+# is only the ceiling. See issue #35, and tests/test_shutdown.py enforces it.
+TimeoutStopSec=30
 # ── Sandboxing / hardening ──
 NoNewPrivileges=true
 PrivateTmp=true

main.py

@@ -8,7 +8,7 @@
 from config import COGS, COMMAND_PREFIX, DISCORD_TOKEN
 from utils import errors
 from utils.help import build as build_help
-from utils.startup import start as start_bot
+from utils.startup import serve
 
 config.configure_logging()
 config.log_runtime()
@@ -60,8 +60,9 @@ async def main():
                 log.info("Loaded cog: %s", cog)
             except Exception:
                 log.exception("Failed to load cog: %s", cog)
-        # Not bot.start(): the login half of it needs retrying.
-        await start_bot(bot, DISCORD_TOKEN)
+        # Not bot.start(): the login needs retrying, and voice has to be
+        # released within a bound before close() waits it out. See utils.startup.
+        await serve(bot, DISCORD_TOKEN)
 
 
 if __name__ == "__main__":

tests/test_shutdown.py

@@ -0,0 +1,215 @@
+"""
+Shutting down inside the time systemd allows.
+
+Issue #35: a restart of a bot that had joined a voice channel timed out, got
+SIGKILLed, and tripped the OnFailure alert. The cause is arithmetic, not a race.
+
+``Client.close()`` disconnects every voice client, and discord.py reuses the
+*connect* timeout as the deadline for Discord to confirm the departure:
+
+    # discord/voice_state.py
+    await asyncio.wait_for(self._disconnected.wait(), timeout=self.timeout)
+
+This bot connects with ``timeout=20`` and the unit allowed ``TimeoutStopSec=15``,
+so a shutdown that was merely being patient was killed 5 seconds early — and
+because all of it happens inside ``async with bot``, the ``except
+KeyboardInterrupt`` handler never ran, which is why no shutdown line was logged.
+
+A bot that never joined voice has no voice client to wait on, which is why every
+other shutdown looked clean.
+"""
+
+import asyncio
+import os
+import re
+import signal
+import sys
+from pathlib import Path
+
+import pytest
+
+from cogs.music import VOICE_CONNECT_TIMEOUT
+from utils.startup import VOICE_DISCONNECT_TIMEOUT, leave_voice, serve
+
+TOKEN = "not-a-real-token"
+PROJECT_ROOT = Path(__file__).resolve().parent.parent
+
+
+class FakeVoice:
+    """A voice client that can disconnect, hang forever, or fail."""
+
+    def __init__(self, *, hangs: bool = False, raises: Exception | None = None) -> None:
+        self.hangs = hangs
+        self.raises = raises
+        self.disconnected = False
+        self.forced: bool | None = None
+
+    async def disconnect(self, *, force: bool) -> None:
+        self.forced = force
+        if self.raises is not None:
+            raise self.raises
+        if self.hangs:
+            await asyncio.sleep(3600)
+        self.disconnected = True
+
+
+class FakeBot:
+    def __init__(self, *voices, login_error: Exception | None = None) -> None:
+        self.voice_clients = list(voices)
+        self._login_error = login_error
+        self.calls: list[str] = []
+
+    async def login(self, token: str) -> None:
+        self.calls.append("login")
+        if self._login_error is not None:
+            raise self._login_error
+
+    async def connect(self, **kwargs) -> None:
+        self.calls.append("connect")
+        await asyncio.sleep(3600)        # a real gateway loop never returns
+
+
+# -- leaving voice, bounded --------------------------------------------
+
+async def test_every_voice_client_is_disconnected():
+    first, second = FakeVoice(), FakeVoice()
+
+    await leave_voice(FakeBot(first, second))
+
+    assert first.disconnected and second.disconnected
+    assert first.forced is True, "a shutdown is not the moment to be polite"
+
+
+async def test_a_disconnect_that_never_returns_is_abandoned():
+    """The regression itself: this used to hang past systemd's patience."""
+    stuck = FakeVoice(hangs=True)
+
+    await asyncio.wait_for(leave_voice(FakeBot(stuck), timeout=0.05), timeout=2.0)
+
+    assert stuck.forced is True, "it was asked to leave"
+    assert not stuck.disconnected, "and it never confirmed"
+
+
+async def test_one_stuck_client_does_not_strand_the_others():
+    stuck, healthy = FakeVoice(hangs=True), FakeVoice()
+
+    await leave_voice(FakeBot(stuck, healthy), timeout=0.05)
+
+    assert healthy.disconnected
+
+
+async def test_a_failing_disconnect_does_not_stop_the_rest():
+    broken, healthy = FakeVoice(raises=RuntimeError("gateway gone")), FakeVoice()
+
+    await leave_voice(FakeBot(broken, healthy), timeout=0.05)
+
+    assert healthy.disconnected
+
+
+async def test_a_bot_that_never_joined_voice_has_nothing_to_do():
+    await leave_voice(FakeBot())
+
+
+# -- serve: run, then shut down ----------------------------------------
+
+async def test_serve_returns_when_asked_to_stop():
+    stop = asyncio.Event()
+    bot = FakeBot()
+    stop.set()
+
+    await asyncio.wait_for(serve(bot, TOKEN, stop=stop), timeout=2.0)
+
+
+async def test_serve_leaves_voice_on_the_way_out():
+    """
+    The whole point: voice is released in our own bounded step, so ``bot.close()``
+    finds nothing left to wait 20 seconds for.
+    """
+    voice = FakeVoice()
+    stop = asyncio.Event()
+    stop.set()
+
+    await asyncio.wait_for(serve(FakeBot(voice), TOKEN, stop=stop), timeout=2.0)
+
+    assert voice.disconnected
+
+
+async def test_serve_leaves_voice_even_when_a_stuck_client_will_not_go():
+    stuck = FakeVoice(hangs=True)
+    stop = asyncio.Event()
+    stop.set()
+
+    await asyncio.wait_for(
+        serve(FakeBot(stuck), TOKEN, stop=stop, voice_timeout=0.05), timeout=2.0)
+
+    assert stuck.forced is True
+
+
+async def test_serve_propagates_a_login_failure():
+    """A broken deployment must still reach systemd."""
+    import discord
+
+    bot = FakeBot(login_error=discord.LoginFailure("bad token"))
+
+    with pytest.raises(discord.LoginFailure):
+        await asyncio.wait_for(serve(bot, TOKEN, stop=asyncio.Event()), timeout=2.0)
+
+
+async def test_serve_still_releases_voice_when_the_login_fails():
+    import discord
+
+    voice = FakeVoice()
+    bot = FakeBot(voice, login_error=discord.LoginFailure("bad token"))
+
+    with pytest.raises(discord.LoginFailure):
+        await asyncio.wait_for(serve(bot, TOKEN, stop=asyncio.Event()), timeout=2.0)
+
+    assert voice.disconnected
+
+
+# -- the arithmetic that caused #35 ------------------------------------
+
+def unit_setting(name: str) -> float:
+    """Read a systemd setting out of the deploy script that writes the unit."""
+    script = (PROJECT_ROOT / "deploy" / "install-units.sh").read_text(encoding="utf-8")
+    match = re.search(rf"^{name}=(\d+)", script, re.MULTILINE)
+    assert match, f"{name} is not set in deploy/install-units.sh"
+    return float(match.group(1))
+
+
+def test_systemd_waits_longer_than_a_voice_disconnect_can():
+    """
+    The bug, as a test. discord.py can spend the whole connect timeout waiting
+    for Discord to confirm a voice departure, and does it for every voice client
+    while closing. If the unit allows less than that, systemd kills a shutdown
+    that was going to finish — taking the child reaping with it.
+    """
+    assert unit_setting("TimeoutStopSec") > VOICE_CONNECT_TIMEOUT
+
+
+def test_our_own_voice_teardown_is_far_inside_that_budget():
+    """Normal shutdowns must be quick, not merely survivable."""
+    assert VOICE_DISCONNECT_TIMEOUT * 2 < unit_setting("TimeoutStopSec")
+
+
+# -- the real signal path ----------------------------------------------
+
+@pytest.mark.skipif(sys.platform == "win32",
+                    reason="loop.add_signal_handler is POSIX-only")
+async def test_a_real_stop_signal_ends_serve():
+    """
+    Production never injects the event — systemd sends a signal.
+
+    Worth its own test because ``add_signal_handler`` is POSIX-only, so the
+    path that actually runs on the server is the one the other tests skip. If
+    the handler were not installed, this SIGTERM would kill the test run
+    outright rather than fail it.
+    """
+    voice = FakeVoice()
+    task = asyncio.create_task(serve(FakeBot(voice), TOKEN))
+    await asyncio.sleep(0.1)                  # let the handler be installed
+
+    os.kill(os.getpid(), signal.SIGTERM)
+
+    await asyncio.wait_for(task, timeout=3.0)
+    assert voice.disconnected, "a signalled shutdown must release voice too"

utils/startup.py

@@ -14,7 +14,9 @@
 """
 
 import asyncio
+import contextlib
 import logging
+import signal
 
 import aiohttp
 import discord
@@ -97,3 +99,80 @@ async def start(bot, token: str, **retry_options) -> None:
     """
     await login_with_retry(bot, token, **retry_options)
     await bot.connect(reconnect=True)
+
+
+# How long to give one voice client to confirm it has left. discord.py's own
+# wait is the *connect* timeout (see cogs.music.VOICE_CONNECT_TIMEOUT), which is
+# far more than a shutdown can afford, so the teardown below bounds it.
+VOICE_DISCONNECT_TIMEOUT = 5.0
+
+_STOP_SIGNALS = ("SIGINT", "SIGTERM")
+
+
+async def leave_voice(bot, *, timeout: float = VOICE_DISCONNECT_TIMEOUT) -> None:
+    """
+    Leave every voice channel, giving each one a bounded chance to confirm.
+
+    ``Client.close()`` would do this too, but it waits the full connect timeout
+    per client with no bound of its own. On a supervised host that is how a
+    shutdown overruns ``TimeoutStopSec`` and gets SIGKILLed — which then skips
+    the child reaping that killing FFmpeg and yt-dlp depends on. Releasing voice
+    here first leaves ``close()`` nothing to be patient about.
+    """
+    for voice in list(getattr(bot, "voice_clients", ())):
+        try:
+            await asyncio.wait_for(voice.disconnect(force=True), timeout=timeout)
+        except asyncio.TimeoutError:
+            log.warning("Voice disconnect did not confirm in %.0fs; abandoning it",
+                        timeout)
+        except Exception:
+            log.warning("Voice disconnect failed", exc_info=True)
+
+
+def _watch_for_stop_signals(stop: asyncio.Event) -> None:
+    """Ask the loop to set ``stop`` on SIGINT/SIGTERM, where it can."""
+    loop = asyncio.get_running_loop()
+    for name in _STOP_SIGNALS:
+        signal_number = getattr(signal, name, None)
+        if signal_number is None:
+            continue
+        try:
+            loop.add_signal_handler(signal_number, stop.set)
+        except (NotImplementedError, RuntimeError):
+            # Windows has no add_signal_handler; there KeyboardInterrupt still
+            # unwinds through serve()'s finally, which is what matters.
+            pass
+
+
+async def serve(bot, token: str, *,
+                stop: asyncio.Event | None = None,
+                voice_timeout: float = VOICE_DISCONNECT_TIMEOUT,
+                **retry_options) -> None:
+    """
+    Run the bot until it is asked to stop, then release voice within a bound.
+
+    The stop signal is turned into an event rather than left as a
+    ``KeyboardInterrupt``, so the teardown runs as ordinary code instead of
+    during exception unwinding — where every further ``await`` in a cancelled
+    task would raise immediately and skip the cleanup.
+    """
+    if stop is None:
+        stop = asyncio.Event()
+        _watch_for_stop_signals(stop)
+
+    running = asyncio.create_task(start(bot, token, **retry_options))
+    stopping = asyncio.create_task(stop.wait())
+    try:
+        done, _ = await asyncio.wait({running, stopping},
+                                     return_when=asyncio.FIRST_COMPLETED)
+        if running in done:
+            running.result()        # a real failure must still reach systemd
+    finally:
+        stopping.cancel()
+        # Only await a task still in flight. Awaiting one that already failed
+        # would re-raise its error here and skip the voice teardown below.
+        if not running.done():
+            running.cancel()
+            with contextlib.suppress(asyncio.CancelledError):
+                await running
+        await leave_voice(bot, timeout=voice_timeout)