diff --git a/app/discord_bot.py b/app/discord_bot.py index 8f7386c..f901281 100644 --- a/app/discord_bot.py +++ b/app/discord_bot.py @@ -53,7 +53,14 @@ from zoneinfo import ZoneInfo from apscheduler.schedulers.asyncio import AsyncIOScheduler from apscheduler.triggers.cron import CronTrigger -from discord import Forbidden, HTTPException, Intents, NotFound +from discord import ( + Forbidden, + HTTPException, + Intents, + LoginFailure, + NotFound, + PrivilegedIntentsRequired, +) from discord.ext import commands from dotenv import load_dotenv from sqlalchemy.exc import SQLAlchemyError @@ -98,6 +105,33 @@ USER_CACHE_MAX = 512 CHECK_EMOJI = '✅' # Green checkmark CROSS_EMOJI = '❌' # Red X +#: First wait before restarting a bot that stopped (OPS-004). Short, because +#: the common case is a brief network blip. +BOT_RESTART_DELAY_SECONDS = 5 + +#: Ceiling on that wait. Five minutes is late enough not to hammer Discord +#: through a long outage, early enough that nobody plans an evening around +#: the reminder never arriving. +BOT_RESTART_MAX_DELAY_SECONDS = 300 + +#: A connection that lasted this long counts as healthy, and resets the +#: back-off. Without it, a bot that ran for a month and then dropped would +#: wait five minutes before its first retry, on the strength of an incident +#: that is long over. +BOT_RESTART_RESET_SECONDS = 600 + +#: Notifications waiting for the bot thread. +#: +#: Module level, not per-instance: the supervisor replaces the bot object on +#: every restart, because discord.py cannot reuse a client whose run() has +#: returned. A queue living on the old object would be discarded with it, +#: taking every pending notification along. +message_queue = Queue() + +#: Set to ask the supervisor to stop waiting and return. Only tests set it; +#: in production the thread is a daemon and the process exit ends it. +_stop_bot = threading.Event() + class TeamTryoutsBot(commands.Bot): """Unified Discord bot for Team Tryouts notifications. @@ -123,7 +157,10 @@ class TeamTryoutsBot(commands.Bot): super().__init__(command_prefix='!', intents=intents) self.flask_app = flask_app self.pending_requests = {} # Maps message_id to {type, id} for reaction handling - self.message_queue = Queue() # Thread-safe queue for messages from Flask + # The shared module-level queue, not a new one: a restart builds a + # fresh bot, and notifications queued against the old one must not + # go with it (OPS-004). + self.message_queue = message_queue self.scheduler = AsyncIOScheduler() self.timezone = ZoneInfo('America/Toronto') # EDT timezone self._user_cache = {} # Discord snowflake -> User, bounded (PERF-005) @@ -1293,12 +1330,25 @@ class TeamTryoutsBot(commands.Bot): bot_instance = None bot_thread = None +#: The application the bot binds its database work to. Held separately from +#: the instance because the supervisor discards the instance on restart and +#: has to build the next one with the same application (OPS-004). +bot_flask_app = None + def get_bot(flask_app=None): - """Get or create the bot instance.""" - global bot_instance + """Get or create the bot instance. + + Falls back to the application the supervisor was started with, so that + a bot rebuilt after a disconnection still reaches the database — the + caller that has the application is `create_app`, and it only calls this + once (OPS-004). + """ + global bot_instance, bot_flask_app + if flask_app is not None: + bot_flask_app = flask_app if bot_instance is None: - bot_instance = TeamTryoutsBot(flask_app=flask_app) + bot_instance = TeamTryoutsBot(flask_app=flask_app or bot_flask_app) elif flask_app is not None and bot_instance.flask_app is None: bot_instance.flask_app = flask_app return bot_instance @@ -1410,26 +1460,90 @@ def send_one_on_one_response( ) +def supervise_bot(run_once=False): + """Keep a Discord bot running, or say clearly why one will not be. + + `bot.run()` returning means the connection is gone for good — discord.py + reconnects on its own for anything recoverable. What happened next was + nothing: the thread ended, `bot_thread` stayed non-None so `start_bot` + would never start another, and the web application went on serving pages + while every notification and every daily reminder had stopped. Nothing + reported it; the outage could last weeks (OPS-004). + + Two kinds of ending are told apart, because retrying helps with exactly + one of them. A rejected token or a missing privileged intent is a + configuration error: retrying it accomplishes nothing except hammering + Discord's login endpoint, which is how an application gets rate-limited + or banned outright. Everything else is treated as an outage and retried + with an exponential back-off, capped, for as long as the process lives. + + The back-off resets after a connection that lasted. Otherwise a bot that + runs happily for a month and then drops would wait five minutes before + its first retry, having "learned" from an incident that is long over. + + Args: + run_once: Stop after a single attempt. For tests — the production + caller never sets it. + """ + global bot_instance + + delay = BOT_RESTART_DELAY_SECONDS + while True: + # A fresh instance every time, deliberately. discord.py closes the + # client when run() returns, and a closed Client will not log in + # again — reusing it is how a "restart" turns into a thread that + # spins on an exception. This is also why message_queue lives at + # module level: a queue on the old object would take every pending + # notification with it. + bot = get_bot(flask_app=bot_flask_app) + started = time.monotonic() + + try: + bot.run(DISCORD_BOT_TOKEN) + except (LoginFailure, PrivilegedIntentsRequired) as exc: + logger.error( + 'The Discord bot cannot log in (%s). This is a configuration error, ' + 'not an outage: retrying would only hammer the login endpoint. No ' + 'notification will be sent until the token or the intents are fixed ' + 'and the process is restarted.', + type(exc).__name__, + ) + return + except Exception: # top of a thread; there is nothing above to catch it + logger.exception('The Discord bot stopped on an unhandled error') + else: + logger.error('The Discord bot disconnected and did not recover on its own') + + bot_instance = None + + if time.monotonic() - started >= BOT_RESTART_RESET_SECONDS: + delay = BOT_RESTART_DELAY_SECONDS + + if run_once: + return + + logger.warning( + 'Restarting the Discord bot in %ds. Notifications are not being sent ' + 'until it reconnects.', + delay, + ) + if _stop_bot.wait(delay): + logger.info('Discord bot supervisor asked to stop.') + return + delay = min(delay * 2, BOT_RESTART_MAX_DELAY_SECONDS) + + def start_bot(flask_app=None): - """Start the Discord bot in the background.""" - global bot_thread + """Start the supervised Discord bot in a background thread.""" + global bot_thread, bot_flask_app + + if flask_app is not None: + bot_flask_app = flask_app + get_bot(flask_app=flask_app) - bot = get_bot(flask_app=flask_app) if DISCORD_BOT_TOKEN and bot_thread is None: - - def run_bot(): - try: - bot.run(DISCORD_BOT_TOKEN) - except Exception: # top of a thread; there is nothing above to catch it - logger.exception('The Discord bot thread stopped on an unhandled error') - finally: - # bot.run() returning means the connection is gone for good: - # discord.py reconnects on its own for anything recoverable. - # Recording it is what makes bot_status() able to say 'stopped' - # instead of reporting a dead thread as running. - logger.error('Discord bot loop exited; notifications are no longer being sent') - - bot_thread = threading.Thread(target=run_bot, daemon=True) + _stop_bot.clear() + bot_thread = threading.Thread(target=supervise_bot, daemon=True) bot_thread.start() logger.info("TeamTryoutsBot started in background thread") elif not DISCORD_BOT_TOKEN: diff --git a/tests/test_discord_state.py b/tests/test_discord_state.py index 877c770..0b9edf3 100644 --- a/tests/test_discord_state.py +++ b/tests/test_discord_state.py @@ -17,6 +17,7 @@ These tests drive the bot object directly. Nothing here talks to Discord. """ import json +import logging import os import time @@ -192,3 +193,158 @@ class TestHealthReporting: payload = client.get('/health').get_json() assert 'discord_bot' not in payload + + +class TestTheSupervisorRestartsTheBot: + """OPS-004 — nothing used to restart it. + + `bot.run()` returning means the connection is gone for good; discord.py + reconnects on its own for anything recoverable. The thread then ended, + `bot_thread` stayed non-None so `start_bot` would never start another, + and the web application kept serving pages while every notification and + every daily reminder had stopped. The outage could last weeks. + """ + + @pytest.fixture + def supervisor(self, monkeypatch): + """Drive supervise_bot without a network, a token or a real client. + + Returns a recorder holding the sequence of fake bots that were built + and how long the supervisor waited between them. + """ + + class Recorder: + def __init__(self): + self.built = [] + self.waits = [] + self.outcomes = [] + + recorder = Recorder() + + class FakeBot: + def __init__(self, outcome): + self.outcome = outcome + + def run(self, _token): + # Returning is what discord.py does on a clean disconnection; + # raising is the other half of what the supervisor separates. + if isinstance(self.outcome, Exception): + raise self.outcome + + def fake_get_bot(flask_app=None): + outcome = recorder.outcomes.pop(0) if recorder.outcomes else None + bot = FakeBot(outcome) + recorder.built.append(bot) + return bot + + def fake_wait(seconds): + recorder.waits.append(seconds) + # False means "not asked to stop", so the loop continues. The + # test bounds the run by emptying `outcomes` and setting the + # event, never by sleeping. + return recorder.stop_after_waits <= len(recorder.waits) + + recorder.stop_after_waits = 1 + monkeypatch.setattr(discord_bot, 'get_bot', fake_get_bot) + monkeypatch.setattr(discord_bot, 'DISCORD_BOT_TOKEN', 'token-not-real') + monkeypatch.setattr(discord_bot._stop_bot, 'wait', fake_wait) + monkeypatch.setattr(discord_bot, 'bot_instance', None) + return recorder + + def test_a_disconnection_builds_a_new_bot(self, supervisor, monkeypatch): + """A fresh instance, not the old one: discord.py closes the client + when run() returns and a closed client will not log in again.""" + supervisor.stop_after_waits = 2 + + discord_bot.supervise_bot() + + assert len(supervisor.built) == 2, 'the supervisor did not try again' + assert supervisor.built[0] is not supervisor.built[1] + + def test_the_wait_grows_between_attempts(self, supervisor): + supervisor.stop_after_waits = 4 + + discord_bot.supervise_bot() + + assert supervisor.waits == [5, 10, 20, 40] + + def test_the_wait_is_capped(self, supervisor): + supervisor.stop_after_waits = 12 + + discord_bot.supervise_bot() + + assert max(supervisor.waits) == discord_bot.BOT_RESTART_MAX_DELAY_SECONDS + assert supervisor.waits[-1] == discord_bot.BOT_RESTART_MAX_DELAY_SECONDS + + def test_a_rejected_token_is_not_retried(self, supervisor, caplog): + """Retrying a bad token accomplishes nothing except hammering the + login endpoint, which is how an application gets rate-limited.""" + from discord import LoginFailure + + supervisor.outcomes = [LoginFailure('Improper token has been passed.')] + supervisor.stop_after_waits = 99 + + discord_bot.supervise_bot() + + assert supervisor.waits == [], 'a configuration error must not be retried' + assert len(supervisor.built) == 1 + + def test_a_rejected_token_says_it_is_a_configuration_error(self, supervisor, caplog): + from discord import LoginFailure + + supervisor.outcomes = [LoginFailure('Improper token has been passed.')] + + package_logger = logging.getLogger('app') + previous = package_logger.propagate + package_logger.propagate = True + try: + with caplog.at_level(logging.ERROR, logger='app.discord_bot'): + discord_bot.supervise_bot() + finally: + package_logger.propagate = previous + + assert 'configuration error' in caplog.text + assert 'not an outage' in caplog.text + + def test_an_unexpected_error_is_retried(self, supervisor): + """The other branch: anything that is not a login refusal is treated + as an outage.""" + supervisor.outcomes = [RuntimeError('gateway exploded')] + supervisor.stop_after_waits = 2 + + discord_bot.supervise_bot() + + assert len(supervisor.built) == 2 + + def test_a_connection_that_lasted_resets_the_backoff(self, supervisor, monkeypatch): + """Otherwise a bot that ran for a month and then dropped waits five + minutes before its first retry, on the strength of an incident that + is long over.""" + clock = {'now': 0.0} + + def fake_monotonic(): + # Every run() call is deemed to have lasted longer than the + # reset threshold. + clock['now'] += discord_bot.BOT_RESTART_RESET_SECONDS + 1 + return clock['now'] + + monkeypatch.setattr(discord_bot.time, 'monotonic', fake_monotonic) + supervisor.stop_after_waits = 3 + + discord_bot.supervise_bot() + + assert supervisor.waits == [5, 5, 5], 'the back-off should not have grown' + + +class TestTheQueueSurvivesARestart: + def test_it_is_shared_by_every_instance(self, monkeypatch): + """A queue living on the bot object would be discarded with it on + each restart, taking every pending notification along.""" + monkeypatch.setattr(discord_bot, 'bot_instance', None) + first = discord_bot.get_bot() + monkeypatch.setattr(discord_bot, 'bot_instance', None) + second = discord_bot.get_bot() + + assert first is not second + assert first.message_queue is second.message_queue + assert first.message_queue is discord_bot.message_queue