diff --git a/app/app.py b/app/app.py index 299b448..3c66a05 100644 --- a/app/app.py +++ b/app/app.py @@ -364,6 +364,17 @@ def create_app(config=None): 'version': '1.0.0', } + # The bot runs in a daemon thread inside this process. When it dies + # the site keeps serving pages and every notification stops, with + # nothing to see from outside — which is how it stayed unnoticed. + # Reported, not fatal: a club without Discord reminders is degraded, + # not down, and a 503 here would take the site out of the load + # balancer for it (OPS-012). + if app.config['ENABLE_DISCORD_BOT']: + from app.discord_bot import bot_status + + health_data['discord_bot'] = bot_status() + # Check database connectivity try: db.session.execute(text('SELECT 1')) diff --git a/app/discord_bot.py b/app/discord_bot.py index 46d5fb4..3e10e6a 100644 --- a/app/discord_bot.py +++ b/app/discord_bot.py @@ -9,6 +9,8 @@ This module provides a persistent bot that handles: import os import json import logging +import tempfile +import time import asyncio import threading import traceback @@ -33,6 +35,14 @@ PENDING_FILE = os.path.join( ) # Emoji constants +#: Entries older than this are dropped when the file is loaded: a message +#: nobody reacted to in a month will not be reacted to (OPS-007). +PENDING_MAX_AGE_DAYS = 30 + +#: How late the daily reminder may still be sent. Long enough to survive a +#: restart or a slow start-up, short of the next day's occurrence. +REMINDER_GRACE_SECONDS = 3600 + CHECK_EMOJI = '✅' # Green checkmark CROSS_EMOJI = '❌' # Red X @@ -66,28 +76,99 @@ class TeamTryoutsBot(commands.Bot): self.timezone = ZoneInfo('America/Toronto') # EDT timezone def _load_pending(self): - """Load pending requests from the JSON file.""" + """Load pending requests from the JSON file. + + A corrupt file used to be logged at error level and then silently + replaced by an empty dict: every in-flight Discord reaction stopped + having any effect, and nothing said so (OPS-006). The file is now + moved aside instead of overwritten, so the mapping can be recovered + by hand, and the message says what was lost. + + Entries older than PENDING_MAX_AGE_DAYS are dropped here rather + than kept forever (OPS-007). A message nobody reacted to in a month + is not going to be reacted to. + """ + if not os.path.exists(PENDING_FILE): + logger.info('No pending requests file found, starting fresh.') + return + try: - if os.path.exists(PENDING_FILE): - with open(PENDING_FILE) as f: - data = json.load(f) - # Convert string keys back to int - self.pending_requests = {int(k): v for k, v in data.items()} - logger.info( - f"Loaded {len(self.pending_requests)} pending requests from {PENDING_FILE}" - ) - else: - logger.info("No pending requests file found, starting fresh.") - except Exception as e: - logger.error(f"Error loading pending requests: {e}") + with open(PENDING_FILE, encoding='utf-8') as handle: + data = json.load(handle) + if not isinstance(data, dict): + raise ValueError(f'expected an object, found {type(data).__name__}') + # Keys are Discord message ids; JSON turns them into strings. + loaded = {int(key): value for key, value in data.items()} + except (OSError, ValueError) as exc: + quarantine = f'{PENDING_FILE}.corrupt-{int(time.time())}' + try: + os.replace(PENDING_FILE, quarantine) + except OSError: + quarantine = '(could not be moved aside)' + logger.error( + 'Pending requests file unreadable (%s). Moved to %s. Reactions on ' + 'messages already sent will no longer be recognised until those ' + 'requests are answered in the web interface.', + exc, + quarantine, + ) + return + + kept, expired = self._drop_expired(loaded) + self.pending_requests = kept + logger.info( + 'Loaded %d pending requests from %s (%d expired and dropped)', + len(kept), + PENDING_FILE, + expired, + ) + if expired: + self._save_pending() + + @staticmethod + def _drop_expired(entries): + """Split loaded entries into the ones still worth keeping. + + Args: + entries: message_id → record. + + Returns: + tuple[dict, int]: Entries to keep, and how many were dropped. + A record without a timestamp predates this field and is kept — + dropping it would be guessing. + """ + cutoff = time.time() - PENDING_MAX_AGE_DAYS * 86400 + kept = {} + expired = 0 + for message_id, record in entries.items(): + created = record.get('created_at') if isinstance(record, dict) else None + if created is not None and created < cutoff: + expired += 1 + continue + kept[message_id] = record + return kept, expired def _save_pending(self): - """Save pending requests to the JSON file.""" + """Write the pending requests to disk, atomically. + + The previous version opened the destination for writing and then + serialised into it: an interruption anywhere in between left a + truncated JSON file, which the loader could not read. Writing to a + neighbouring temporary file and renaming means the destination is + either the old content or the new one, never half of either. + """ + directory = os.path.dirname(PENDING_FILE) or '.' try: - with open(PENDING_FILE, 'w') as f: - json.dump(self.pending_requests, f, indent=2) - except Exception as e: - logger.error(f"Error saving pending requests: {e}") + with tempfile.NamedTemporaryFile( + 'w', encoding='utf-8', dir=directory, prefix='.pending-', delete=False + ) as handle: + json.dump(self.pending_requests, handle, indent=2) + handle.flush() + os.fsync(handle.fileno()) + temporary = handle.name + os.replace(temporary, PENDING_FILE) + except OSError as exc: + logger.error('Could not save pending requests: %s', exc) async def setup_hook(self): """Called when the bot is ready.""" @@ -109,13 +190,26 @@ class TeamTryoutsBot(commands.Bot): self.loop.create_task(self.start_scheduler()) async def start_scheduler(self): - """Start the APScheduler for daily reminders.""" + """Start the APScheduler for daily reminders. + + `coalesce` and `misfire_grace_time` are the two settings this job + needs and did not have (OPS-005). Without a grace time, a restart at + 18:05 dropped the day's reminders with no trace; without coalescing, + a scheduler that wakes up behind schedule fires once per missed run, + so players receive the same reminder several times. + + The grace period is deliberately short of the next occurrence: a + reminder for tonight is worth sending an hour late, not tomorrow. + """ try: self.scheduler.add_job( self.send_daily_reminders, trigger=CronTrigger(hour=18, minute=0, timezone=self.timezone), id='daily_reminders', replace_existing=True, + coalesce=True, + misfire_grace_time=REMINDER_GRACE_SECONDS, + max_instances=1, ) self.scheduler.start() logger.info('Daily reminder scheduler started (18:00 EDT)') @@ -269,7 +363,11 @@ class TeamTryoutsBot(commands.Bot): await msg.add_reaction(CROSS_EMOJI) # Track this pending request - self.pending_requests[msg.id] = {'type': 'one_on_one', 'id': request_id} + self.pending_requests[msg.id] = { + 'type': 'one_on_one', + 'id': request_id, + 'created_at': time.time(), + } self._save_pending() logger.info(f"Sent One on One DM with reactions, message_id={msg.id}") @@ -339,6 +437,7 @@ class TeamTryoutsBot(commands.Bot): 'type': 'schedule_addition', 'id': reference_id, 'event_type': event_type, + 'created_at': time.time(), } self._save_pending() @@ -460,25 +559,73 @@ class TeamTryoutsBot(commands.Bot): except Exception as e: logger.error(f"Error handling rejection: {e}\n{traceback.format_exc()}") + @staticmethod + def _attendance_record(event_type, reference_id): + """The row an attendance reaction refers to, and whose it is. + + Args: + event_type: 'match' or 'tryout'. + reference_id: Primary key of the participation row. + + Returns: + tuple: (row, player_id) — either may be None. + """ + from app.models import MatchParticipant, TryoutRegistration + + if event_type == 'match': + row = MatchParticipant.query.get(reference_id) + elif event_type == 'tryout': + row = TryoutRegistration.query.get(reference_id) + else: + row = None + return row, getattr(row, 'player_id', None) + + @staticmethod + def _reacting_user_owns(player_id, reacting_user): + """Whether the Discord account that reacted is the row's owner. + + handle_one_on_one_approve and _reject have always compared the + reacting account against the coach the request was sent to. The two + attendance handlers did not (OPS-009) — same message shape, same + threat, one of them checked. The asymmetry was the bug. + """ + from app.models import User + + if not player_id: + return False + owner = User.query.get(player_id) + return bool(owner and owner.discord_user_id == str(reacting_user.id)) + async def handle_attendance_confirm(self, player, message_id, reference_id, channel): """Handle player confirming attendance for a match/tryout.""" try: - from app.models import MatchParticipant, TryoutRegistration from app.extensions import db request_info = self.pending_requests[message_id] event_type = request_info.get('event_type') + row, player_id = self._attendance_record(event_type, reference_id) - if event_type == 'match': - participant = MatchParticipant.query.get(reference_id) - if participant: - participant = db.session.merge(participant) - participant.attendance_confirmed = True - elif event_type == 'tryout': - registration = TryoutRegistration.query.get(reference_id) - if registration: - registration = db.session.merge(registration) - registration.attendance_confirmed = True + if row is not None and not self._reacting_user_owns(player_id, player): + await channel.send("⚠️ You are not the intended recipient.") + return + + if row is not None: + row = db.session.merge(row) + if event_type == 'match': + row.attendance_confirmed = True + else: + # TryoutRegistration has no attendance_confirmed column + # (DB-008, waiting on Alembic). Assigning here sets a + # Python attribute that is never written, so the player + # was told "confirmed" and nothing was recorded. Still + # true — but no longer silent. + logger.warning( + 'Tryout attendance confirmation from user_id=%s for ' + 'registration %s was not persisted: TryoutRegistration ' + 'has no attendance_confirmed column (DB-008).', + player.id, + reference_id, + ) db.session.commit() @@ -492,22 +639,22 @@ class TeamTryoutsBot(commands.Bot): async def handle_attendance_decline(self, player, message_id, reference_id, channel): """Handle player declining attendance for a match/tryout.""" try: - from app.models import MatchParticipant, TryoutRegistration from app.extensions import db request_info = self.pending_requests[message_id] event_type = request_info.get('event_type') + row, player_id = self._attendance_record(event_type, reference_id) - if event_type == 'match': - participant = MatchParticipant.query.get(reference_id) - if participant: - participant = db.session.merge(participant) - db.session.delete(participant) - elif event_type == 'tryout': - registration = TryoutRegistration.query.get(reference_id) - if registration: - registration = db.session.merge(registration) - registration.status = 'no_show' + if row is not None and not self._reacting_user_owns(player_id, player): + await channel.send("⚠️ You are not the intended recipient.") + return + + if row is not None: + row = db.session.merge(row) + if event_type == 'match': + db.session.delete(row) + else: + row.status = 'no_show' db.session.commit() @@ -880,9 +1027,40 @@ def start_bot(flask_app=None): bot.run(DISCORD_BOT_TOKEN) except Exception as e: logger.error(f"Bot error: {e}") + 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) bot_thread.start() logger.info("TeamTryoutsBot started in background thread") elif not DISCORD_BOT_TOKEN: logger.warning("DISCORD_BOT_TOKEN not set, bot not started") + + +def bot_status(): + """What the bot is doing, for /health (OPS-012). + + The bot runs in a daemon thread inside the web process. When that + thread dies — a revoked token, a fatal gateway error — the web + application keeps serving pages and no notification is ever sent again. + Nothing reported it, so nobody found out until someone asked why they + had stopped receiving reminders. + + Returns: + dict: `configured` (a token is set), `running` (the thread is + alive), `connected` (the gateway session is up) and `pending` + (reaction mappings held in memory). + """ + running = bool(bot_thread and bot_thread.is_alive()) + instance = bot_instance + connected = bool(instance and not instance.is_closed() and instance.is_ready()) + return { + 'configured': bool(DISCORD_BOT_TOKEN), + 'running': running, + 'connected': connected, + 'pending': len(instance.pending_requests) if instance else 0, + } diff --git a/discord_pending.json b/discord_pending.json deleted file mode 100644 index 9e26dfe..0000000 --- a/discord_pending.json +++ /dev/null @@ -1 +0,0 @@ -{} \ No newline at end of file diff --git a/tests/test_discord_state.py b/tests/test_discord_state.py new file mode 100644 index 0000000..520f183 --- /dev/null +++ b/tests/test_discord_state.py @@ -0,0 +1,180 @@ +"""The bot's on-disk state and what /health says about it. + +OPS-005/006/007/012. Four defects that shared a shape: the bot could stop +working correctly, and nothing anywhere said so. + + - a truncated pending file was logged and then silently replaced by an + empty dict, so every in-flight Discord reaction stopped having an + effect; + - the file was written in place, so any interruption produced exactly + that truncated file; + - entries were never removed unless someone reacted, so the file grew + for ever; + - when the bot thread died, the site kept serving pages and every + notification stopped, invisibly. + +These tests drive the bot object directly. Nothing here talks to Discord. +""" + +import json +import os +import time + +import pytest + +from app import discord_bot +from app.discord_bot import PENDING_MAX_AGE_DAYS, TeamTryoutsBot + + +@pytest.fixture +def bot(monkeypatch, tmp_path): + """A bot whose pending file lives in a throwaway directory.""" + pending = tmp_path / 'discord_pending.json' + monkeypatch.setattr(discord_bot, 'PENDING_FILE', str(pending)) + instance = TeamTryoutsBot.__new__(TeamTryoutsBot) + instance.pending_requests = {} + return instance, pending + + +class TestSaving: + def test_a_saved_file_reloads(self, bot): + instance, pending = bot + instance.pending_requests = {123: {'type': 'one_on_one', 'id': 5}} + instance._save_pending() + + instance.pending_requests = {} + instance._load_pending() + + assert instance.pending_requests == {123: {'type': 'one_on_one', 'id': 5}} + + def test_no_temporary_file_is_left_behind(self, bot): + instance, pending = bot + instance.pending_requests = {1: {'type': 'one_on_one', 'id': 1}} + instance._save_pending() + + leftovers = [name for name in os.listdir(pending.parent) if name.startswith('.pending-')] + assert leftovers == [] + + def test_the_previous_content_survives_a_failed_write(self, bot, monkeypatch): + """Writing in place was the whole problem: an interruption left a + half-written file that the loader could not read.""" + instance, pending = bot + instance.pending_requests = {1: {'type': 'one_on_one', 'id': 1}} + instance._save_pending() + + def _explode(*args, **kwargs): + raise OSError('disk full') + + monkeypatch.setattr(discord_bot.tempfile, 'NamedTemporaryFile', _explode) + instance.pending_requests = {2: {'type': 'one_on_one', 'id': 2}} + instance._save_pending() + + assert json.loads(pending.read_text(encoding='utf-8')) == { + '1': {'type': 'one_on_one', 'id': 1} + } + + +class TestLoading: + def test_a_missing_file_starts_empty(self, bot): + instance, _pending = bot + instance._load_pending() + assert instance.pending_requests == {} + + def test_a_truncated_file_is_moved_aside_not_overwritten(self, bot, caplog): + """Losing the mapping is bad; losing it *and* the evidence is worse.""" + instance, pending = bot + pending.write_text('{"123": {"type": "one_on', encoding='utf-8') + + instance._load_pending() + + assert instance.pending_requests == {} + quarantined = [name for name in os.listdir(pending.parent) if '.corrupt-' in name] + assert len(quarantined) == 1 + assert not pending.exists() + + def test_a_json_document_that_is_not_an_object_is_refused(self, bot): + instance, pending = bot + pending.write_text('[1, 2, 3]', encoding='utf-8') + + instance._load_pending() + + assert instance.pending_requests == {} + assert any('.corrupt-' in name for name in os.listdir(pending.parent)) + + def test_stale_entries_are_dropped(self, bot): + instance, pending = bot + old = time.time() - (PENDING_MAX_AGE_DAYS + 1) * 86400 + pending.write_text( + json.dumps( + { + '1': {'type': 'one_on_one', 'id': 1, 'created_at': old}, + '2': {'type': 'one_on_one', 'id': 2, 'created_at': time.time()}, + } + ), + encoding='utf-8', + ) + + instance._load_pending() + + assert list(instance.pending_requests) == [2] + + def test_the_purge_is_written_back(self, bot): + instance, pending = bot + old = time.time() - (PENDING_MAX_AGE_DAYS + 1) * 86400 + pending.write_text( + json.dumps({'1': {'type': 'one_on_one', 'id': 1, 'created_at': old}}), + encoding='utf-8', + ) + + instance._load_pending() + + assert json.loads(pending.read_text(encoding='utf-8')) == {} + + def test_an_entry_without_a_timestamp_is_kept(self, bot): + """Records written before this field existed. Dropping them would + be guessing at their age.""" + instance, pending = bot + pending.write_text(json.dumps({'1': {'type': 'one_on_one', 'id': 1}}), encoding='utf-8') + + instance._load_pending() + + assert list(instance.pending_requests) == [1] + + +class TestHealthReporting: + def test_the_status_shape_is_stable(self, monkeypatch): + """An external probe reads these keys; they are the contract.""" + monkeypatch.setattr(discord_bot, 'bot_thread', None) + monkeypatch.setattr(discord_bot, 'bot_instance', None) + + status = discord_bot.bot_status() + + assert set(status) == {'configured', 'running', 'connected', 'pending'} + assert status['running'] is False + assert status['connected'] is False + + def test_a_dead_thread_reads_as_not_running(self, monkeypatch): + class DeadThread: + @staticmethod + def is_alive(): + return False + + monkeypatch.setattr(discord_bot, 'bot_thread', DeadThread()) + monkeypatch.setattr(discord_bot, 'bot_instance', None) + + assert discord_bot.bot_status()['running'] is False + + def test_health_reports_the_bot_when_it_is_enabled(self, app): + """The suite runs with the bot disabled, so this builds an app that + claims otherwise rather than starting anything.""" + app.config['ENABLE_DISCORD_BOT'] = True + + payload = app.test_client().get('/health').get_json() + + assert 'discord_bot' in payload + assert payload['status'] == 'healthy' + + def test_health_stays_quiet_when_the_bot_is_off(self, app, client): + payload = client.get('/health').get_json() + + assert 'discord_bot' not in payload