diff --git a/app/discord_bot.py b/app/discord_bot.py index 6c7a784..8f7386c 100644 --- a/app/discord_bot.py +++ b/app/discord_bot.py @@ -4,6 +4,40 @@ This module provides a persistent bot that handles: - One on One request approvals/rejections via reactions - Match/tryout schedule addition notifications with attendance confirmation - Daily reminders at 18:00 EDT for upcoming events + +Three families of failure, and what each one does (ARCH-008 / QUA-004) +---------------------------------------------------------------------- + +Every handler in this file used to wrap its whole body in one +`try/except Exception` that logged and carried on. A database refusal, a +closed inbox and a typo in this module all produced the same line, and the +person who clicked the reaction was told nothing either way. The handlers +now separate three cases, because they need three different answers: + +1. **The database refused the write** — `SQLAlchemyError`. The session is + rolled back, the pending entry is kept so the same reaction can be tried + again, and the person is told that nothing was recorded. Silence here was + the worst of the three: a confirmation that failed to commit looked + exactly like a bot that was not running. + +2. **Discord could not be reached** — `HTTPException` and its subclasses + (`Forbidden`, `NotFound`). Expected, per recipient, and already named one + by one in `_send_dm`. After a commit these are best-effort: the decision + is recorded whether or not the message got through, and undoing it + because a DM bounced would be worse than the bounce. + +3. **Anything else is a defect** — it propagates. `on_error` records it with + its traceback, under this application's logger rather than discord.py's. + A defect that reads like a delivery failure never gets fixed. + +Four catches are still broad, and all four are boundaries with nothing above +them to catch anything: the queue loop, the APScheduler job, the thread the +bot runs in, and the hand-off from a Flask request. Each says on its line why. + +Ruff's `BLE` rule is enabled (QUA-004), and what it enforces is not "never +catch broadly" — it is satisfied by logging the traceback. Which is the +whole discipline: a boundary may swallow anything, provided it leaves behind +enough to tell a defect from an outage. """ import asyncio @@ -13,7 +47,6 @@ import os import tempfile import threading import time -import traceback from datetime import datetime, timedelta from queue import Empty, Queue from zoneinfo import ZoneInfo @@ -23,6 +56,7 @@ from apscheduler.triggers.cron import CronTrigger from discord import Forbidden, HTTPException, Intents, NotFound from discord.ext import commands from dotenv import load_dotenv +from sqlalchemy.exc import SQLAlchemyError load_dotenv() DISCORD_BOT_TOKEN = os.getenv('DISCORD_BOT_TOKEN') @@ -93,6 +127,10 @@ class TeamTryoutsBot(commands.Bot): self.scheduler = AsyncIOScheduler() self.timezone = ZoneInfo('America/Toronto') # EDT timezone self._user_cache = {} # Discord snowflake -> User, bounded (PERF-005) + #: Whether the 18:00 reminder job is actually scheduled. Starts False + #: and is only set by start_scheduler succeeding, so /health reports + #: 'not yet' rather than guessing (ARCH-008). + self.reminders_scheduled = False def _load_pending(self): """Load pending requests from the JSON file. @@ -194,12 +232,33 @@ class TeamTryoutsBot(commands.Bot): self._load_pending() logger.info(f'TeamTryoutsBot logged in as {self.user}') + async def on_error(self, event_method, *args, **kwargs): + """Record an exception that escaped an event handler. + + This is the third family: not a database refusal, not Discord being + unreachable — a defect. discord.py's own handler logs it on the + `discord` logger, which `configure_logging` does not wire to any of + this application's files: it attaches handlers to the `app` package + (logging_config.py). So an unexpected failure inside a reaction + handler went to a logger nobody reads, and the reaction looked + ignored. + + Deliberately says nothing to the user. At this point what did and did + not happen is exactly what is unknown, and a reassuring message would + be a guess. + """ + logger.exception( + 'Unhandled exception in %s. This is a defect, not a delivery failure: ' + 'expected Discord and database errors are handled where they occur.', + event_method, + ) + async def on_ready(self): """Log when the bot is ready and start background tasks.""" try: guilds = [g.name for g in self.guilds] logger.info(f'TeamTryoutsBot is ready! Logged in as {self.user} | Guilds: {guilds}') - except Exception: + except AttributeError: logger.info(f'TeamTryoutsBot is ready! Logged in as {self.user}') # Start the queue processing task @@ -219,6 +278,12 @@ class TeamTryoutsBot(commands.Bot): The grace period is deliberately short of the next occurrence: a reminder for tonight is worth sending an hour late, not tomorrow. + + A failure here is permanent and total — no reminder is ever sent + again — and used to leave one line in a log. It is now visible from + outside, in /health, because that is the difference between finding + out at start-up and finding out when a player asks why the reminders + stopped (ARCH-008). """ try: self.scheduler.add_job( @@ -231,9 +296,67 @@ class TeamTryoutsBot(commands.Bot): max_instances=1, ) self.scheduler.start() - logger.info('Daily reminder scheduler started (18:00 EDT)') - except Exception as e: - logger.error(f'Error starting scheduler: {e}') + except Exception: # a scheduler that will not start must not take on_ready with it + self.reminders_scheduled = False + logger.exception( + 'Daily reminder scheduler could not be started. No reminder will be ' + 'sent until the process is restarted; /health reports this.' + ) + return + + self.reminders_scheduled = True + logger.info('Daily reminder scheduler started (18:00 EDT)') + + async def _reply(self, channel, message): + """Answer the person who reacted, and never let that answer be fatal. + + Returns True when it went out. A reply is the only feedback a + reaction gets, so a failed one is worth a line — but it must not undo + a state change that has already been committed. + """ + try: + await channel.send(message) + except HTTPException as exc: + logger.error('Could not answer a reaction on Discord: %s', exc) + return False + return True + + async def _commit_or_report(self, channel, *, operation): + """Make the pending change durable, or say plainly that it is not. + + Returns True when the write landed. On a database refusal the session + is rolled back, the pending entry is left in place so the same + reaction can be tried again, and the person is told that nothing was + recorded — previously the failure was logged and the coroutine + returned, which is indistinguishable from the bot being down. + + Anything that is not a database error propagates: it is a defect, and + on_error records it as one. + """ + from app.extensions import db + + try: + db.session.commit() + except SQLAlchemyError: + db.session.rollback() + logger.exception('%s was not recorded: the database refused the write', operation) + await self._reply( + channel, + "⚠️ Nothing was recorded — the database refused the change. " + "Please answer from the web interface instead.", + ) + return False + return True + + def _forget_pending(self, message_id): + """Drop a message from the pending map, once its answer is durable. + + `pop` rather than `del`: two reactions on the same message race + through two coroutines, and the loser raised KeyError inside the old + blanket handler, where it read as an error with no consequence. + """ + if self.pending_requests.pop(message_id, None) is not None: + self._save_pending() async def _resolve_user(self, discord_uid, *, context=''): """Return the Discord user behind a snowflake, or None. @@ -317,29 +440,46 @@ class TeamTryoutsBot(commands.Bot): logger.info('Delivered %s to %s (message_id=%s)', purpose, who, sent.id) return sent + async def _dispatch(self, item): + """Send one queued notification, inside an app context where needed.""" + kind = item.get('type') + if kind == 'one_on_one_request': + await self._send_one_on_one_dm(**item['data']) + elif kind == 'schedule_addition': + if self.flask_app: + with self.flask_app.app_context(): + await self._send_schedule_notification(**item['data']) + else: + await self._send_schedule_notification(**item['data']) + elif kind == 'one_on_one_response': + await self._send_one_on_one_response_dm(**item['data']) + else: + logger.error('Unknown queue item type %r; the notification was dropped', kind) + async def process_queue(self): - """Process messages from the queue (runs continuously).""" + """Drain the queue fed by the Flask threads, for the life of the bot. + + The loop is the last thing standing between one bad item and every + subsequent notification, so it catches everything. What reaches it is + narrower than it used to be: `_send_dm` already reports a closed inbox + or an outage per recipient and returns None, so anything arriving here + got past the typed handling and is a defect. It reads as one. + """ while True: try: - try: - item = self.message_queue.get_nowait() - except Empty: - await asyncio.sleep(0.5) - continue + item = self.message_queue.get_nowait() + except Empty: + await asyncio.sleep(0.5) + continue - if item.get('type') == 'one_on_one_request': - await self._send_one_on_one_dm(**item['data']) - elif item.get('type') == 'schedule_addition': - if self.flask_app: - with self.flask_app.app_context(): - await self._send_schedule_notification(**item['data']) - else: - await self._send_schedule_notification(**item['data']) - elif item.get('type') == 'one_on_one_response': - await self._send_one_on_one_response_dm(**item['data']) - - except Exception as e: - logger.error(f"Error processing queue: {e}\n{traceback.format_exc()}") + try: + await self._dispatch(item) + except Exception: # the loop must outlive a single bad item + logger.exception( + 'Unexpected failure while sending a %r notification. It is lost; ' + 'delivery failures that are merely expected do not reach here.', + item.get('type'), + ) await asyncio.sleep(0.1) def is_dm_channel(self, channel) -> bool: @@ -359,7 +499,16 @@ class TeamTryoutsBot(commands.Bot): # Fetch the channel and check if it's a DM try: channel = await self.fetch_channel(payload.channel_id) - except Exception: + except HTTPException as exc: + # Silent before. The reaction is now unanswerable — there is no + # channel to answer in — so the log line is the only trace there + # will ever be that someone clicked and nothing happened. + logger.warning( + 'Could not open the channel of a reaction on message %s: %s. ' + 'The reaction was not acted on.', + payload.message_id, + exc, + ) return if not self.is_dm_channel(channel): @@ -555,17 +704,33 @@ class TeamTryoutsBot(commands.Bot): return msg.id async def handle_one_on_one_approve(self, coach, message_id, request_id, channel): - """Handle coach approving a One on One request.""" - try: - from app.extensions import db - from app.models import OneOnOneRequest + """Record a coach's approval, then tell the coach and the player. + Four steps, and they do not fail alike: read the request and stage + the change (database), commit it (database, and the only step whose + failure means nothing happened), answer the coach (Discord), tell the + player (Discord). Everything after the commit is best-effort by + definition — the decision is recorded, and a DM that bounces does not + un-record it. + """ + from app.extensions import db + from app.models import OneOnOneRequest + + try: request = OneOnOneRequest.query.get(request_id) if not request: + # The row is gone; no reaction on this message can ever mean + # anything again. Keeping the mapping is what PENDING_MAX_AGE_DAYS + # was invented to bound. + logger.info( + 'One on One request %s no longer exists; its pending message was dropped.', + request_id, + ) + self._forget_pending(message_id) return if request.coach.discord_user_id != str(coach.id): - await channel.send("⚠️ You are not the intended recipient.") + await self._reply(channel, "⚠️ You are not the intended recipient.") return # Re-attach to current session (object may be detached across app contexts) @@ -578,39 +743,62 @@ class TeamTryoutsBot(commands.Bot): request.status = 'approved' request.responded_at = datetime.utcnow() - db.session.commit() + except SQLAlchemyError: + db.session.rollback() + logger.exception('Could not read One on One request %s to approve it', request_id) + await self._reply( + channel, + "⚠️ Nothing was recorded — the request could not be read. " + "Please answer from the web interface instead.", + ) + return - await channel.send( - f"✅ You have **approved** the One on One session with {player_full_name}." + if not await self._commit_or_report( + channel, operation=f'Approval of One on One request {request_id}' + ): + return + + # Durable from here. Order matters: forget the pending entry before + # the two messages, so that a bounced DM cannot leave a request that + # is already approved answerable a second time. + self._forget_pending(message_id) + + await self._reply( + channel, f"✅ You have **approved** the One on One session with {player_full_name}." + ) + + if player_discord_id: + await self.notify_player_about_one_on_one_direct( + player_discord_id=player_discord_id, + player_full_name=player_full_name, + coach_full_name=coach_obj.full_name if coach_obj else 'Coach', + request=request, + approved=True, ) - # Notify player via Discord - if player_discord_id: - await self.notify_player_about_one_on_one_direct( - player_discord_id=player_discord_id, - player_full_name=player_full_name, - coach_full_name=coach_obj.full_name if coach_obj else 'Coach', - request=request, - approved=True, - ) - del self.pending_requests[message_id] - self._save_pending() - - except Exception as e: - logger.error(f"Error handling approval: {e}\n{traceback.format_exc()}") - async def handle_one_on_one_reject(self, coach, message_id, request_id, channel): - """Handle coach rejecting a One on One request.""" - try: - from app.extensions import db - from app.models import OneOnOneRequest + """Record a coach's refusal, with the reason they replied, if any. + Same four steps as the approval, plus a fifth that fails on its own + terms: reading back the coach's reply to find a refusal note. That + one is optional by construction — a refusal without a note is a + refusal — so it is caught where it happens and the rest continues. + """ + from app.extensions import db + from app.models import OneOnOneRequest + + try: request = OneOnOneRequest.query.get(request_id) if not request: + logger.info( + 'One on One request %s no longer exists; its pending message was dropped.', + request_id, + ) + self._forget_pending(message_id) return if request.coach.discord_user_id != str(coach.id): - await channel.send("⚠️ You are not the intended recipient.") + await self._reply(channel, "⚠️ You are not the intended recipient.") return # Re-attach to current session (object may be detached across app contexts) @@ -619,49 +807,68 @@ class TeamTryoutsBot(commands.Bot): player_full_name = request.player.full_name if request.player else 'Unknown' player_discord_id = request.player.discord_user_id if request.player else None coach_obj = request.coach + except SQLAlchemyError: + db.session.rollback() + logger.exception('Could not read One on One request %s to reject it', request_id) + await self._reply( + channel, + "⚠️ Nothing was recorded — the request could not be read. " + "Please answer from the web interface instead.", + ) + return - refusal_note = None - try: - async for reply in channel.history(limit=20): - if ( - reply.author.id == coach.id - and reply.reference - and reply.reference.message_id == message_id - ): - refusal_note = reply.content - break - except Exception as e: - logger.warning(f"Could not check for reply message: {e}") + refusal_note = None + try: + async for reply in channel.history(limit=20): + if ( + reply.author.id == coach.id + and reply.reference + and reply.reference.message_id == message_id + ): + refusal_note = reply.content + break + except HTTPException as exc: + logger.warning( + 'Could not read the channel history for a refusal note on request %s: %s. ' + 'The refusal is still recorded, without a reason.', + request_id, + exc, + ) + try: request.status = 'rejected' request.responded_at = datetime.utcnow() if refusal_note: request.coach_rejection_message = refusal_note - db.session.commit() + except SQLAlchemyError: + db.session.rollback() + logger.exception('Could not stage the refusal of One on One request %s', request_id) + await self._reply(channel, "⚠️ Nothing was recorded. Please use the web interface.") + return - rejection_msg = ( - f"❌ You have **rejected** the One on One session with {player_full_name}." + if not await self._commit_or_report( + channel, operation=f'Refusal of One on One request {request_id}' + ): + return + + self._forget_pending(message_id) + + rejection_msg = f"❌ You have **rejected** the One on One session with {player_full_name}." + if refusal_note: + rejection_msg += f"\n**Reason:** {refusal_note}" + else: + rejection_msg += "\n\nℹ️ The player has been notified that you are not available." + + await self._reply(channel, rejection_msg) + if player_discord_id: + await self.notify_player_about_one_on_one_direct( + player_discord_id=player_discord_id, + player_full_name=player_full_name, + coach_full_name=coach_obj.full_name if coach_obj else 'Coach', + request=request, + approved=False, + refusal_note=refusal_note, ) - if refusal_note: - rejection_msg += f"\n**Reason:** {refusal_note}" - else: - rejection_msg += "\n\nℹ️ The player has been notified that you are not available." - - await channel.send(rejection_msg) - if player_discord_id: - await self.notify_player_about_one_on_one_direct( - player_discord_id=player_discord_id, - player_full_name=player_full_name, - coach_full_name=coach_obj.full_name if coach_obj else 'Coach', - request=request, - approved=False, - refusal_note=refusal_note, - ) - del self.pending_requests[message_id] - self._save_pending() - - except Exception as e: - logger.error(f"Error handling rejection: {e}\n{traceback.format_exc()}") @staticmethod def _attendance_record(event_type, reference_id): @@ -701,16 +908,29 @@ class TeamTryoutsBot(commands.Bot): 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.extensions import db + """Record a player confirming attendance for a match or tryout. - request_info = self.pending_requests[message_id] - event_type = request_info.get('event_type') + This is the handler the audit used to describe ARCH-008. The player + was told "✅ Your attendance has been confirmed!" from inside the same + blanket handler that swallowed the commit — so a database refusal + produced no message at all, and the reaction was indistinguishable + from a bot that had stopped running. The commit and the message are + now separate steps with separate outcomes. + """ + from app.extensions import db + + request_info = self.pending_requests.get(message_id) + if request_info is None: + # Two awaits happened since on_raw_reaction_add checked; the + # other reaction on the same message got here first. + return + event_type = request_info.get('event_type') + + try: row, player_id = self._attendance_record(event_type, reference_id) if row is not None and not self._reacting_user_owns(player_id, player): - await channel.send("⚠️ You are not the intended recipient.") + await self._reply(channel, "⚠️ You are not the intended recipient.") return if row is not None: @@ -730,27 +950,46 @@ class TeamTryoutsBot(commands.Bot): player.id, reference_id, ) + except SQLAlchemyError: + db.session.rollback() + logger.exception( + 'Could not read the %s participation row %s to confirm attendance', + event_type, + reference_id, + ) + await self._reply( + channel, + "⚠️ Nothing was recorded. Please confirm from the web interface instead.", + ) + return - db.session.commit() + if not await self._commit_or_report( + channel, operation=f'Attendance confirmation for {event_type} row {reference_id}' + ): + return - await channel.send("✅ Your attendance has been confirmed!") - del self.pending_requests[message_id] - self._save_pending() - - except Exception as e: - logger.error(f"Error handling attendance confirmation: {e}\n{traceback.format_exc()}") + self._forget_pending(message_id) + await self._reply(channel, "✅ Your attendance has been confirmed!") async def handle_attendance_decline(self, player, message_id, reference_id, channel): - """Handle player declining attendance for a match/tryout.""" - try: - from app.extensions import db + """Record a player declining attendance for a match or tryout. - request_info = self.pending_requests[message_id] - event_type = request_info.get('event_type') + The mirror of handle_attendance_confirm, and the same reasoning: a + declined match deletes a participation row, which is exactly the kind + of write a foreign key can refuse. The player now hears about it. + """ + from app.extensions import db + + request_info = self.pending_requests.get(message_id) + if request_info is None: + return + event_type = request_info.get('event_type') + + try: row, player_id = self._attendance_record(event_type, reference_id) if row is not None and not self._reacting_user_owns(player_id, player): - await channel.send("⚠️ You are not the intended recipient.") + await self._reply(channel, "⚠️ You are not the intended recipient.") return if row is not None: @@ -759,15 +998,26 @@ class TeamTryoutsBot(commands.Bot): db.session.delete(row) else: row.status = 'no_show' + except SQLAlchemyError: + db.session.rollback() + logger.exception( + 'Could not read the %s participation row %s to decline attendance', + event_type, + reference_id, + ) + await self._reply( + channel, + "⚠️ Nothing was recorded. Please answer from the web interface instead.", + ) + return - db.session.commit() + if not await self._commit_or_report( + channel, operation=f'Attendance refusal for {event_type} row {reference_id}' + ): + return - await channel.send("❌ Your attendance has been declined.") - del self.pending_requests[message_id] - self._save_pending() - - except Exception as e: - logger.error(f"Error handling attendance decline: {e}\n{traceback.format_exc()}") + self._forget_pending(message_id) + await self._reply(channel, "❌ Your attendance has been declined.") async def notify_player_about_one_on_one_direct( self, @@ -790,79 +1040,93 @@ class TeamTryoutsBot(commands.Bot): request: The OneOnOneRequest object (for date/time/points data only). approved: Whether the session was approved. refusal_note: Optional coach refusal reason. + + Catches nothing of its own. Every caller reaches this after the + coach's answer is committed, so a failure here costs the player a + message and nothing else — and if it is a defect (a request whose + date is None, say) it must be seen as one, in on_error, rather than + flattened into "Error in direct One on One notification". """ - try: - if not player_discord_id: - logger.warning(f"Player has no Discord user ID for request {request.id}") - return + if not player_discord_id: + logger.warning('Player has no Discord user ID for request %s', request.id) + return - if approved: - message = ( - "🎉 **One on One Session Confirmed!**\n\n" - f"Your coach **{coach_full_name}** has approved your request:\n" - f"**Date:** {request.date.strftime('%A, %B %d, %Y')}\n" - f"**Time:** {request.start_time.strftime('%I:%M %p')} - {request.end_time.strftime('%I:%M %p')}\n" - f"**Discussion Points:** {request.points or 'No specific points provided'}\n\n" - "Please prepare for your session!" - ) - else: - if refusal_note: - message = ( - "😞 **One on One Session Rejected**\n\n" - f"Your coach **{coach_full_name}** has declined:\n" - f"**Reason:** {refusal_note}\n\n" - "Please try selecting a different time slot." - ) - else: - message = ( - "😞 **One on One Session Unavailable**\n\n" - f"Your coach **{coach_full_name}** is not available.\n\n" - "Please try selecting a different time slot." - ) - - await self._send_dm( - player_discord_id, - message, - purpose=f'one-on-one response (request {request.id})', - recipient=player_full_name, + if approved: + message = ( + "🎉 **One on One Session Confirmed!**\n\n" + f"Your coach **{coach_full_name}** has approved your request:\n" + f"**Date:** {request.date.strftime('%A, %B %d, %Y')}\n" + f"**Time:** {request.start_time.strftime('%I:%M %p')} - {request.end_time.strftime('%I:%M %p')}\n" + f"**Discussion Points:** {request.points or 'No specific points provided'}\n\n" + "Please prepare for your session!" + ) + elif refusal_note: + message = ( + "😞 **One on One Session Rejected**\n\n" + f"Your coach **{coach_full_name}** has declined:\n" + f"**Reason:** {refusal_note}\n\n" + "Please try selecting a different time slot." + ) + else: + message = ( + "😞 **One on One Session Unavailable**\n\n" + f"Your coach **{coach_full_name}** is not available.\n\n" + "Please try selecting a different time slot." ) - except Exception as e: - logger.error(f"Error in direct One on One notification: {e}") + await self._send_dm( + player_discord_id, + message, + purpose=f'one-on-one response (request {request.id})', + recipient=player_full_name, + ) async def send_daily_reminders(self): - """Send daily reminders at 18:00 EDT for events in 24-48 hours.""" + """Run the 18:00 batch. The APScheduler job boundary. + + Broad on purpose: nothing above this is ours. An exception escaping + an APScheduler job is logged by the library and the job stays + scheduled, but the line it writes says nothing about what this batch + was doing, and it lands on a logger this application does not + collect. + """ try: if self.flask_app: with self.flask_app.app_context(): await self._send_daily_reminders_impl() else: await self._send_daily_reminders_impl() - except Exception as e: - logger.error(f"Error sending daily reminders: {e}\n{traceback.format_exc()}") + except Exception: # a failed batch must not unschedule tomorrow's + logger.exception('The daily reminder batch failed. Tomorrow’s run is unaffected.') async def _send_daily_reminders_impl(self): - """Internal implementation of daily reminders with proper app context.""" + """Internal implementation of daily reminders with proper app context. + + Only the database is caught here. A batch that cannot read the + schedule has nothing to send and is worth one clear line; a batch + that fails for any other reason is a defect and belongs in the + traceback that send_daily_reminders writes. + """ + from sqlalchemy.orm import joinedload + + from app.models import ( + Match, + MatchParticipant, + OneOnOneRequest, + Tryout, + TryoutRegistration, + ) + + now = datetime.now(self.timezone) + tomorrow = now.date() + timedelta(days=1) + + # Counted so that a partial run is visible as such. Per-recipient + # failures are logged by _send_dm; without this total, a batch in + # which half the reminders bounced looked exactly like one where + # they all went out (PERF-005). + attempted = delivered = 0 + try: - from sqlalchemy.orm import joinedload - - from app.models import ( - Match, - MatchParticipant, - OneOnOneRequest, - Tryout, - TryoutRegistration, - ) - - now = datetime.now(self.timezone) - tomorrow = now.date() + timedelta(days=1) - - # Counted so that a partial run is visible as such. Per-recipient - # failures are logged by _send_dm; without this total, a batch in - # which half the reminders bounced looked exactly like one where - # they all went out (PERF-005). - attempted = delivered = 0 - # Find matches for tomorrow matches = Match.query.filter(Match.date == tomorrow).all() for match in matches: @@ -893,21 +1157,26 @@ class TeamTryoutsBot(commands.Bot): if session.player and session.player.discord_user_id: attempted += 1 delivered += await self.send_one_on_one_reminder(session.player, session) + except SQLAlchemyError: + db_reached = f'{delivered} of {attempted} sent before it stopped' + logger.exception( + 'The daily reminder batch for %s could not read the schedule (%s)', + tomorrow, + db_reached, + ) + return - if attempted and delivered < attempted: - logger.warning( - 'Daily reminders for %s: %d of %d delivered, %d failed. See the ' - 'lines above for who and why.', - tomorrow, - delivered, - attempted, - attempted - delivered, - ) - else: - logger.info('Daily reminders for %s: %d delivered', tomorrow, delivered) - - except Exception as e: - logger.error(f"Error sending daily reminders: {e}") + if attempted and delivered < attempted: + logger.warning( + 'Daily reminders for %s: %d of %d delivered, %d failed. See the ' + 'lines above for who and why.', + tomorrow, + delivered, + attempted, + attempted - delivered, + ) + else: + logger.info('Daily reminders for %s: %d delivered', tomorrow, delivered) async def send_match_reminder(self, player, match): """Send match reminder to player. True if it was delivered.""" @@ -960,48 +1229,47 @@ class TeamTryoutsBot(commands.Bot): """Send a DM to a player notifying them of their One on One request response. Called from the message queue when a coach accepts/rejects via the web app. + + Every argument is a string prepared by the caller, and _send_dm + already handles a closed inbox and an outage. There is nothing left + for a blanket catch to protect against, so anything that goes wrong + here is a defect and process_queue records it as one. """ - try: - if not player_discord_id: - logger.warning("Cannot send response DM: no player_discord_id") - return False - - if approved: - message = ( - "🎉 **One on One Session Confirmed!**\n\n" - f"Your coach **{coach_full_name}** has approved your request:\n" - f"**Date:** {date_str}\n" - f"**Time:** {start_time} - {end_time}\n" - f"**Discussion Points:** {points or 'No specific points provided'}\n\n" - "Please prepare for your session!" - ) - else: - if refusal_note: - message = ( - "😞 **One on One Session Rejected**\n\n" - f"Your coach **{coach_full_name}** has declined:\n" - f"**Reason:** {refusal_note}\n\n" - "Please try selecting a different time slot." - ) - else: - message = ( - "😞 **One on One Session Unavailable**\n\n" - f"Your coach **{coach_full_name}** is not available.\n\n" - "Please try selecting a different time slot." - ) - - sent = await self._send_dm( - player_discord_id, - message, - purpose=f'one-on-one response ({"approved" if approved else "declined"})', - recipient=player_full_name, - ) - return sent is not None - - except Exception as e: - logger.error(f"Error sending One on One response DM: {e}") + if not player_discord_id: + logger.warning("Cannot send response DM: no player_discord_id") return False + if approved: + message = ( + "🎉 **One on One Session Confirmed!**\n\n" + f"Your coach **{coach_full_name}** has approved your request:\n" + f"**Date:** {date_str}\n" + f"**Time:** {start_time} - {end_time}\n" + f"**Discussion Points:** {points or 'No specific points provided'}\n\n" + "Please prepare for your session!" + ) + elif refusal_note: + message = ( + "😞 **One on One Session Rejected**\n\n" + f"Your coach **{coach_full_name}** has declined:\n" + f"**Reason:** {refusal_note}\n\n" + "Please try selecting a different time slot." + ) + else: + message = ( + "😞 **One on One Session Unavailable**\n\n" + f"Your coach **{coach_full_name}** is not available.\n\n" + "Please try selecting a different time slot." + ) + + sent = await self._send_dm( + player_discord_id, + message, + purpose=f'one-on-one response ({"approved" if approved else "declined"})', + recipient=player_full_name, + ) + return sent is not None + async def send_one_on_one_reminder(self, player, session): """Send One on One reminder to player. True if it was delivered.""" message = ( @@ -1036,6 +1304,28 @@ def get_bot(flask_app=None): return bot_instance +def _enqueue(kind: str, data: dict, *, description: str) -> bool: + """Hand one notification to the bot thread. Never raises. + + The three public senders below were the same fifteen lines three times, + each with its own blanket catch. There is one now, and it is the only + place in this module where breadth is a property of the caller rather + than of the failure: this runs in a Flask request thread, and the work + the notification announces is already committed. The meeting is booked + whether or not Discord hears about it, so a failure here must not become + a 500 on a page whose job is done. + + What it is not is somewhere to lose a defect: the traceback is logged + and the caller is told False. + """ + try: + get_bot().message_queue.put({'type': kind, 'data': data}) + except Exception: # a notification must never fail the request that caused it + logger.exception('Could not queue %s', description) + return False + return True + + def send_one_on_one_dm( coach_name: str, coach_discord_id: str, @@ -1048,28 +1338,21 @@ def send_one_on_one_dm( request_id: int, ) -> bool: """Queue a One on One request DM to be sent by the bot.""" - bot = get_bot() - try: - bot.message_queue.put( - { - 'type': 'one_on_one_request', - 'data': { - 'coach_name': coach_name, - 'coach_discord_id': coach_discord_id, - 'player_name': player_name, - 'team_name': team_name, - 'date_str': date_str, - 'start_time': start_time, - 'end_time': end_time, - 'points': points, - 'request_id': request_id, - }, - } - ) - return True - except Exception as e: - logger.error(f"Error queuing One on One DM: {e}") - return False + return _enqueue( + 'one_on_one_request', + { + 'coach_name': coach_name, + 'coach_discord_id': coach_discord_id, + 'player_name': player_name, + 'team_name': team_name, + 'date_str': date_str, + 'start_time': start_time, + 'end_time': end_time, + 'points': points, + 'request_id': request_id, + }, + description=f'the One on One request DM for request {request_id}', + ) def send_schedule_notification( @@ -1081,25 +1364,18 @@ def send_schedule_notification( reference_id: int, ) -> bool: """Queue a schedule addition notification to be sent by the bot.""" - bot = get_bot() - try: - bot.message_queue.put( - { - 'type': 'schedule_addition', - 'data': { - 'user_id': user_id, - 'event_type': event_type, - 'event_title': event_title, - 'event_date': event_date, - 'event_time': event_time, - 'reference_id': reference_id, - }, - } - ) - return True - except Exception as e: - logger.error(f"Error queuing schedule notification: {e}") - return False + return _enqueue( + 'schedule_addition', + { + 'user_id': user_id, + 'event_type': event_type, + 'event_title': event_title, + 'event_date': event_date, + 'event_time': event_time, + 'reference_id': reference_id, + }, + description=f'the {event_type} notification for user {user_id}', + ) def send_one_on_one_response( @@ -1117,28 +1393,21 @@ def send_one_on_one_response( Called from Flask routes when a coach accepts/rejects via the web app. """ - bot = get_bot() - try: - bot.message_queue.put( - { - 'type': 'one_on_one_response', - 'data': { - 'player_discord_id': player_discord_id, - 'player_full_name': player_full_name, - 'coach_full_name': coach_full_name, - 'date_str': date_str, - 'start_time': start_time, - 'end_time': end_time, - 'points': points, - 'approved': approved, - 'refusal_note': refusal_note, - }, - } - ) - return True - except Exception as e: - logger.error(f"Error queuing One on One response DM: {e}") - return False + return _enqueue( + 'one_on_one_response', + { + 'player_discord_id': player_discord_id, + 'player_full_name': player_full_name, + 'coach_full_name': coach_full_name, + 'date_str': date_str, + 'start_time': start_time, + 'end_time': end_time, + 'points': points, + 'approved': approved, + 'refusal_note': refusal_note, + }, + description=f'the One on One response DM for {player_full_name}', + ) def start_bot(flask_app=None): @@ -1151,8 +1420,8 @@ def start_bot(flask_app=None): def run_bot(): try: bot.run(DISCORD_BOT_TOKEN) - except Exception as e: - logger.error(f"Bot error: {e}") + 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. @@ -1176,10 +1445,15 @@ def bot_status(): Nothing reported it, so nobody found out until someone asked why they had stopped receiving reminders. + `reminders_scheduled` is the second silent-death case (ARCH-008): the + thread can be alive and the gateway connected while the 18:00 job never + got scheduled, in which case nothing is ever sent at 18:00 and the other + three keys all read green. + 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). + alive), `connected` (the gateway session is up), `pending` + (reaction mappings held in memory) and `reminders_scheduled`. """ running = bool(bot_thread and bot_thread.is_alive()) instance = bot_instance @@ -1189,4 +1463,5 @@ def bot_status(): 'running': running, 'connected': connected, 'pending': len(instance.pending_requests) if instance else 0, + 'reminders_scheduled': bool(instance and instance.reminders_scheduled), } diff --git a/tests/test_bot_error_families.py b/tests/test_bot_error_families.py new file mode 100644 index 0000000..919626c --- /dev/null +++ b/tests/test_bot_error_families.py @@ -0,0 +1,430 @@ +"""Three families of failure, and the three different answers they get. + +ARCH-008 / QUA-004. Every handler in `discord_bot.py` used to wrap its +whole body in one `except Exception` that logged a line and returned, so +these three all looked the same from the outside and two of them looked the +same from the inside: + + - the database refused the write — nothing happened, and the person who + clicked has to be told, because a silent reaction is indistinguishable + from a bot that is not running; + - Discord could not be reached — after a commit, the thing is recorded + whether or not the message got through, and must stay recorded; + - something else went wrong — a defect, which has to reach a traceback + rather than be flattened into "Error handling attendance confirmation". + +The coroutines are driven with `asyncio.run` rather than pytest-asyncio, +which the project does not depend on — same convention as +`test_discord_delivery.py`. +""" + +import asyncio +import logging +from datetime import date, time + +import pytest +from discord import HTTPException +from sqlalchemy.exc import OperationalError + +from app import discord_bot +from app.discord_bot import TeamTryoutsBot + + +class FakeChannel: + """The DM channel a reaction came from. Records what it was told to say.""" + + def __init__(self, raises=None): + self.raises = raises + self.sent = [] + + async def send(self, message): + if self.raises is not None: + raise self.raises + self.sent.append(message) + return object() + + +class FakeReactor: + """The Discord account that clicked. Only its snowflake is ever read.""" + + def __init__(self, uid): + self.id = uid + + +def http_error(): + class _Response: + status = 500 + reason = 'test' + + return HTTPException(_Response(), 'Internal Server Error') + + +def database_error(): + """A refusal that is not an IntegrityError. + + Deliberately: the handlers catch `SQLAlchemyError`, and picking the + subclass a constraint violation produces would let a narrower catch + pass this suite while still dropping a lost connection on the floor. + """ + return OperationalError('SELECT 1', {}, Exception('server closed the connection')) + + +@pytest.fixture +def logs(caplog): + """Let the bot's records reach caplog. + + `configure_logging` sets propagate = False on the 'app' logger, and + caplog's handler sits on the root. Without this the assertions below + read an empty log and pass for the wrong reason — the trap recorded in + the wave G notes. + """ + package_logger = logging.getLogger('app') + previous = package_logger.propagate + package_logger.propagate = True + caplog.set_level(logging.INFO, logger='app.discord_bot') + yield caplog + package_logger.propagate = previous + + +@pytest.fixture +def bot(): + """A bot with the state the reaction handlers touch, and nothing else. + + `__new__` because the constructor builds a real discord.py client. + `_save_pending` is replaced: the real one writes `discord_pending.json` + at the repository root. + """ + instance = TeamTryoutsBot.__new__(TeamTryoutsBot) + instance.flask_app = None + instance.pending_requests = {} + instance._user_cache = {} + instance.reminders_scheduled = False + instance.saves = 0 + + def _save(): + instance.saves += 1 + + instance._save_pending = _save + return instance + + +@pytest.fixture +def participation(db, make_user): + """A player on a match, plus the pending message asking them to confirm. + + Returns (participation row id, the player's Discord snowflake). + """ + from app.models import Match, MatchParticipant, Tryout + + snowflake = '4242' + player_id = make_user('player', discord_user_id=snowflake) + admin_id = make_user('admin') + + tryout = Tryout(title='Sélection', game='valorant', date=date(2026, 9, 1), created_by=admin_id) + db.session.add(tryout) + db.session.flush() + + match = Match( + title='Finale', + date=date(2026, 9, 2), + start_time=time(18, 0), + created_by=admin_id, + tryout_id=tryout.id, + match_type='intra', + ) + db.session.add(match) + db.session.flush() + + row = MatchParticipant(match_id=match.id, player_id=player_id) + db.session.add(row) + db.session.commit() + return row.id, snowflake + + +def _pending(bot, message_id, row_id): + bot.pending_requests[message_id] = { + 'type': 'schedule_addition', + 'id': row_id, + 'event_type': 'match', + } + + +def _confirmed(row_id): + from app.models import MatchParticipant + + return MatchParticipant.query.get(row_id).attendance_confirmed + + +class TestTheDatabaseRefusedTheWrite: + def test_the_happy_path_records_the_confirmation(self, bot, db, participation, logs): + """The premise of every test below. Without it they could all pass + against a handler that never records anything at all.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + channel = FakeChannel() + + asyncio.run(bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, channel)) + + assert _confirmed(row_id) is True + assert channel.sent == ["✅ Your attendance has been confirmed!"] + assert 7 not in bot.pending_requests + + def test_a_refused_commit_tells_the_player_instead_of_going_quiet( + self, bot, db, participation, monkeypatch, logs + ): + """The defect ARCH-008 was written about. + + The success message sat inside the same blanket handler as the + commit, so a refused write produced no message at all — the reaction + looked ignored, which is what a stopped bot looks like too. + """ + row_id, snowflake = participation + _pending(bot, 7, row_id) + channel = FakeChannel() + + def refuse(): + raise database_error() + + monkeypatch.setattr(db.session, 'commit', refuse) + + asyncio.run(bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, channel)) + + assert channel.sent, 'silence is the one answer this must never give' + assert 'Nothing was recorded' in channel.sent[0] + # Every message, not just the first: an earlier version of this test + # looked at sent[0] alone, and a handler that reported the refusal + # and then sent "✅ Your attendance has been confirmed!" anyway + # passed it. + assert not any("✅" in message for message in channel.sent), ( + 'a failed write must not be followed by a success message' + ) + + def test_a_refused_commit_leaves_the_row_untouched( + self, bot, db, participation, monkeypatch, logs + ): + row_id, snowflake = participation + _pending(bot, 7, row_id) + + def refuse(): + raise database_error() + + monkeypatch.setattr(db.session, 'commit', refuse) + asyncio.run(bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, FakeChannel())) + + monkeypatch.undo() + assert _confirmed(row_id) is False, ( + 'the handler must roll back; leaving the change pending in the ' + 'session hands it to whatever commits next' + ) + + def test_a_refused_commit_keeps_the_reaction_answerable( + self, bot, db, participation, monkeypatch, logs + ): + """Dropping the pending entry on a failed write would make the + second attempt do nothing, silently, forever.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + + def refuse(): + raise database_error() + + monkeypatch.setattr(db.session, 'commit', refuse) + asyncio.run(bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, FakeChannel())) + + assert 7 in bot.pending_requests + + def test_the_refusal_reaches_the_log_with_its_traceback( + self, bot, db, participation, monkeypatch, logs + ): + row_id, snowflake = participation + _pending(bot, 7, row_id) + + def refuse(): + raise database_error() + + monkeypatch.setattr(db.session, 'commit', refuse) + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + asyncio.run( + bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, FakeChannel()) + ) + + assert any(record.exc_info for record in logs.records), ( + 'a database refusal is diagnosed from the driver error, which only ' + 'the traceback carries' + ) + + def test_a_declined_match_that_cannot_be_deleted_says_so( + self, bot, db, participation, monkeypatch, logs + ): + """The decline path deletes a row, which is exactly what a foreign + key refuses. Same answer as the confirm path.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + channel = FakeChannel() + + def refuse(): + raise database_error() + + monkeypatch.setattr(db.session, 'commit', refuse) + asyncio.run(bot.handle_attendance_decline(FakeReactor(snowflake), 7, row_id, channel)) + + assert channel.sent and 'Nothing was recorded' in channel.sent[0] + assert 7 in bot.pending_requests + + +class TestDiscordCouldNotBeReached: + def test_a_bounced_message_does_not_undo_the_record(self, bot, db, participation, logs): + """The confirmation is committed before the message goes out. A DM + that bounces costs the player a message, not their attendance.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + + asyncio.run( + bot.handle_attendance_confirm( + FakeReactor(snowflake), 7, row_id, FakeChannel(raises=http_error()) + ) + ) + + assert _confirmed(row_id) is True + assert 7 not in bot.pending_requests, ( + 'the answer is durable, so the message must not stay answerable' + ) + + def test_a_bounced_message_is_reported(self, bot, db, participation, logs): + row_id, snowflake = participation + _pending(bot, 7, row_id) + + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + asyncio.run( + bot.handle_attendance_confirm( + FakeReactor(snowflake), 7, row_id, FakeChannel(raises=http_error()) + ) + ) + + assert 'Could not answer a reaction' in logs.text + + +class TestAnythingElseIsADefect: + def test_an_unexpected_failure_propagates(self, bot, db, participation, monkeypatch, logs): + """It used to be caught here and logged as though it were a delivery + problem. Letting it out is what puts it in front of on_error.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + + def boom(event_type, reference_id): + raise ZeroDivisionError('a defect, not an outage') + + monkeypatch.setattr(TeamTryoutsBot, '_attendance_record', staticmethod(boom)) + + with pytest.raises(ZeroDivisionError): + asyncio.run( + bot.handle_attendance_confirm(FakeReactor(snowflake), 7, row_id, FakeChannel()) + ) + + def test_on_error_records_it_under_this_application_s_logger(self, bot, logs): + """discord.py logs escaped event exceptions on the `discord` logger, + which logging_config does not wire to any of this application's + files. That is where these used to go.""" + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + try: + raise ZeroDivisionError('boom') + except ZeroDivisionError: + asyncio.run(bot.on_error('on_raw_reaction_add')) + + assert 'on_raw_reaction_add' in logs.text + assert 'defect' in logs.text + assert any(record.exc_info for record in logs.records) + + +class TestTheQueueBoundary: + def test_queueing_never_raises_into_the_request_that_caused_it(self, monkeypatch, logs): + """This runs in a Flask request thread, after the work it announces + is committed. A notification must not turn a finished page into a + 500 — but it must not swallow the reason either.""" + + def no_bot(): + raise RuntimeError('the bot could not be built') + + monkeypatch.setattr(discord_bot, 'get_bot', no_bot) + + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + queued = discord_bot.send_schedule_notification(1, 'match', 'Finale', 'd', 't', 2) + + assert queued is False + assert any(record.exc_info for record in logs.records) + + def test_a_queued_notification_reaches_the_queue(self, bot, monkeypatch): + """The premise of the test above: the same call succeeds normally.""" + from queue import Queue + + bot.message_queue = Queue() + monkeypatch.setattr(discord_bot, 'get_bot', lambda: bot) + + assert discord_bot.send_schedule_notification(1, 'match', 'Finale', 'd', 't', 2) is True + assert bot.message_queue.get_nowait()['type'] == 'schedule_addition' + + def test_an_unknown_item_type_is_named_and_dropped(self, bot, logs): + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + asyncio.run(bot._dispatch({'type': 'invented', 'data': {}})) + + assert 'invented' in logs.text + + +class TestTheSchedulerSaysWhetherItStarted: + class FailingScheduler: + @staticmethod + def add_job(*args, **kwargs): + raise RuntimeError('no event loop') + + class WorkingScheduler: + def __init__(self): + self.started = False + + def add_job(self, *args, **kwargs): + pass + + def start(self): + self.started = True + + def test_a_scheduler_that_will_not_start_is_visible_from_outside(self, bot, logs): + """The other four /health keys all read green in this state: the + thread is alive, the gateway is up, and no reminder is ever sent.""" + from zoneinfo import ZoneInfo + + bot.scheduler = self.FailingScheduler() + bot.timezone = ZoneInfo('America/Toronto') + + with logs.at_level(logging.ERROR, logger='app.discord_bot'): + asyncio.run(bot.start_scheduler()) + + assert bot.reminders_scheduled is False + assert 'No reminder will be sent' in logs.text + + def test_a_scheduler_that_starts_says_so(self, bot, logs): + from zoneinfo import ZoneInfo + + bot.scheduler = self.WorkingScheduler() + bot.timezone = ZoneInfo('America/Toronto') + + asyncio.run(bot.start_scheduler()) + + assert bot.scheduler.started is True + assert bot.reminders_scheduled is True + + +class TestTwoReactionsOnOneMessage: + def test_the_second_one_finds_nothing_to_do(self, bot, db, participation, logs): + """A confirm and a decline arrive together; both got past the + membership check in on_raw_reaction_add before either finished. The + loser used to raise KeyError inside the blanket handler, where it + read as an error with no consequence.""" + row_id, snowflake = participation + _pending(bot, 7, row_id) + reactor = FakeReactor(snowflake) + + asyncio.run(bot.handle_attendance_confirm(reactor, 7, row_id, FakeChannel())) + second = FakeChannel() + asyncio.run(bot.handle_attendance_decline(reactor, 7, row_id, second)) + + assert second.sent == [], 'the second reaction must not answer twice' + assert _confirmed(row_id) is True diff --git a/tests/test_discord_state.py b/tests/test_discord_state.py index 520f183..877c770 100644 --- a/tests/test_discord_state.py +++ b/tests/test_discord_state.py @@ -143,15 +143,29 @@ class TestLoading: class TestHealthReporting: def test_the_status_shape_is_stable(self, monkeypatch): - """An external probe reads these keys; they are the contract.""" + """An external probe reads these keys; they are the contract. + + `reminders_scheduled` joined them with ARCH-008. The other four can + all read green while the 18:00 job never got scheduled — the thread + is alive, the gateway is up, and no reminder is ever sent. Adding a + key is safe for a probe that looks at the ones it knows; removing or + renaming one is not. + """ 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 set(status) == { + 'configured', + 'running', + 'connected', + 'pending', + 'reminders_scheduled', + } assert status['running'] is False assert status['connected'] is False + assert status['reminders_scheduled'] is False def test_a_dead_thread_reads_as_not_running(self, monkeypatch): class DeadThread: