diff --git a/cogs/music.py b/cogs/music.py index cd9176a..183e58c 100644 --- a/cogs/music.py +++ b/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 diff --git a/deploy/install-units.sh b/deploy/install-units.sh index 8e8fcc1..994105b 100644 --- a/deploy/install-units.sh +++ b/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 diff --git a/main.py b/main.py index 8d394f2..7f6c04b 100644 --- a/main.py +++ b/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__": diff --git a/tests/test_shutdown.py b/tests/test_shutdown.py new file mode 100644 index 0000000..6634614 --- /dev/null +++ b/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" diff --git a/utils/startup.py b/utils/startup.py index bde5e44..6720458 100644 --- a/utils/startup.py +++ b/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)