From 3f221ba13a6f9a80f2049d5dfb4448552d774c5e Mon Sep 17 00:00:00 2001 From: adrunkhuman <16039109+adrunkhuman@users.noreply.github.com> Date: Thu, 21 May 2026 23:25:08 +0200 Subject: [PATCH] chore: trim startup logs --- .env.example | 2 + AGENTS.md | 2 +- README.md | 2 +- tests/test_bot.py | 171 +++++++++++++++++++++++++++++++++++++++++----- typer_bot/bot.py | 136 ++++++++++++++++++++---------------- 5 files changed, 238 insertions(+), 75 deletions(-) diff --git a/.env.example b/.env.example index e02ec44..5114099 100644 --- a/.env.example +++ b/.env.example @@ -30,6 +30,8 @@ DISCORD_TOKEN=your_bot_token_here # Logging (optional) # Levels: DEBUG, INFO, WARNING, ERROR # Logs are plain single-line stdout. +# INFO logs startup, guild joins/removals, and permission warnings. +# DEBUG adds fixture announcement verification details. LOG_LEVEL=INFO # Channel ID for reminders (optional) diff --git a/AGENTS.md b/AGENTS.md index 7a39f80..719151e 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -108,7 +108,7 @@ guild_config ( ``` ## 4. Codebase Map -- `typer_bot/bot.py`: Entry point and setup hook. +- `typer_bot/bot.py`: Entry point, setup hook, startup/guild lifecycle logging, and guild permission checks. - `typer_bot/commands/user_commands.py`: Public slash commands, including modal-driven `/predict` flow. - `typer_bot/commands/admin_panel/`: Admin panel UI views, selects, and modals split out of `admin_commands.py`. - `typer_bot/handlers/thread_prediction_handler.py`: Thread-based prediction processing (on_message) plus thread prediction cooldown state. diff --git a/README.md b/README.md index 1224c0b..fa0fc7a 100644 --- a/README.md +++ b/README.md @@ -77,7 +77,7 @@ uv run python -m typer_bot Disposable non-production deployments can auto-seed an empty database by setting `SEED_TEST_DATA=true` and `TEST_GUILD_ID`. -Logs are plain single-line stdout; set `LOG_LEVEL=DEBUG` when troubleshooting. +Logs are plain single-line stdout. `INFO` includes startup, guild join/remove, setup state, and permission warnings; set `LOG_LEVEL=DEBUG` for fixture announcement verification details. Run checks: diff --git a/tests/test_bot.py b/tests/test_bot.py index e0cbe3a..4d3dead 100644 --- a/tests/test_bot.py +++ b/tests/test_bot.py @@ -3,6 +3,7 @@ import os from contextlib import suppress from datetime import UTC, datetime, timedelta +from types import SimpleNamespace from unittest.mock import AsyncMock, MagicMock, patch import discord @@ -11,6 +12,23 @@ from typer_bot.bot import TyperBot, main +def guild_permissions( + *, + send_messages=True, + send_messages_in_threads=True, + read_message_history=True, + add_reactions=True, + create_public_threads=True, +): + return SimpleNamespace( + send_messages=send_messages, + send_messages_in_threads=send_messages_in_threads, + read_message_history=read_message_history, + add_reactions=add_reactions, + create_public_threads=create_public_threads, + ) + + class TestBotInitialization: """Test suite for bot initialization and setup.""" @@ -174,22 +192,27 @@ async def test_check_permissions_logs_missing_permissions(self, bot_instance): mock_guild.name = "Test Guild" mock_guild.id = 123456 mock_guild.me = MagicMock() - mock_guild.me.guild_permissions.send_messages = False - mock_guild.me.guild_permissions.read_message_history = False - mock_guild.me.guild_permissions.add_reactions = False - mock_guild.me.guild_permissions.create_public_threads = False + mock_guild.me.guild_permissions = guild_permissions( + send_messages=False, + send_messages_in_threads=False, + read_message_history=False, + add_reactions=False, + create_public_threads=False, + ) bot_instance.guilds = [mock_guild] with patch("typer_bot.bot.logger") as mock_logger: await bot_instance._check_permissions() - warning = mock_logger.warning.call_args.args[0] + warning_call = mock_logger.warning.call_args - assert "Test Guild" in warning - assert "Send Messages" in warning - assert "Read Message History" in warning - assert "Add Reactions" in warning - assert "Create Public Threads" in warning + assert warning_call.args[0] == "Guild missing permissions" + assert warning_call.kwargs["extra"]["guild_name"] == "Test Guild" + assert "Send Messages" in warning_call.kwargs["extra"]["missing_permissions"] + assert "Send Messages in Threads" in warning_call.kwargs["extra"]["missing_permissions"] + assert "Read Message History" in warning_call.kwargs["extra"]["missing_permissions"] + assert "Add Reactions" in warning_call.kwargs["extra"]["missing_permissions"] + assert "Create Public Threads" in warning_call.kwargs["extra"]["missing_permissions"] @pytest.mark.asyncio async def test_check_permissions_warns_when_only_thread_permission_missing(self, bot_instance): @@ -198,21 +221,137 @@ async def test_check_permissions_warns_when_only_thread_permission_missing(self, mock_guild.name = "Test Guild" mock_guild.id = 123456 mock_guild.me = MagicMock() - mock_guild.me.guild_permissions.send_messages = True - mock_guild.me.guild_permissions.read_message_history = True - mock_guild.me.guild_permissions.add_reactions = True - mock_guild.me.guild_permissions.create_public_threads = False + mock_guild.me.guild_permissions = guild_permissions(create_public_threads=False) + + bot_instance.guilds = [mock_guild] + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance._check_permissions() + warning_call = mock_logger.warning.call_args + + assert warning_call.args[0] == "Guild missing permissions" + assert "Create Public Threads" in warning_call.kwargs["extra"]["missing_permissions"] + mock_logger.info.assert_not_called() + + @pytest.mark.asyncio + async def test_check_permissions_warns_when_only_thread_send_permission_missing( + self, bot_instance + ): + mock_guild = MagicMock() + mock_guild.name = "Test Guild" + mock_guild.id = 123456 + mock_guild.me = MagicMock() + mock_guild.me.guild_permissions = guild_permissions(send_messages_in_threads=False) bot_instance.guilds = [mock_guild] with patch("typer_bot.bot.logger") as mock_logger: await bot_instance._check_permissions() - warning = mock_logger.warning.call_args.args[0] + warning_call = mock_logger.warning.call_args - assert "Create Public Threads" in warning + assert warning_call.args[0] == "Guild missing permissions" + assert "Send Messages in Threads" in warning_call.kwargs["extra"]["missing_permissions"] mock_logger.info.assert_not_called() +class TestGuildLifecycle: + @pytest.fixture + def bot_instance(self): + with patch("typer_bot.bot.commands.Bot.__init__", return_value=None): + bot = TyperBot.__new__(TyperBot) + bot.db = MagicMock() + bot.db.get_guild_config = AsyncMock(return_value=None) + yield bot + + @pytest.mark.asyncio + async def test_on_guild_join_logs_invite_and_setup_state(self, bot_instance): + guild = MagicMock() + guild.id = 123456 + guild.name = "New Guild" + guild.member_count = 42 + guild.me = MagicMock() + guild.me.guild_permissions = guild_permissions() + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance.on_guild_join(guild) + + bot_instance.db.get_guild_config.assert_awaited_once_with("123456") + info_call = mock_logger.info.call_args + assert info_call.args[0] == "Joined guild" + assert info_call.kwargs["extra"] == { + "guild_id": 123456, + "guild_name": "New Guild", + "member_count": 42, + "setup_configured": False, + } + mock_logger.warning.assert_not_called() + + @pytest.mark.asyncio + async def test_on_guild_join_logs_configured_state(self, bot_instance): + bot_instance.db.get_guild_config.return_value = {"guild_id": "123456"} + guild = MagicMock() + guild.id = 123456 + guild.name = "Configured Guild" + guild.member_count = 10 + guild.me = MagicMock() + guild.me.guild_permissions = guild_permissions() + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance.on_guild_join(guild) + + assert mock_logger.info.call_args.kwargs["extra"]["setup_configured"] is True + + @pytest.mark.asyncio + async def test_on_guild_join_logs_even_when_setup_lookup_fails(self, bot_instance): + bot_instance.db.get_guild_config.side_effect = RuntimeError("db unavailable") + guild = MagicMock() + guild.id = 123456 + guild.name = "New Guild" + guild.member_count = 42 + guild.me = MagicMock() + guild.me.guild_permissions = guild_permissions() + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance.on_guild_join(guild) + + mock_logger.exception.assert_called_once() + info_call = mock_logger.info.call_args + assert info_call.args[0] == "Joined guild" + assert info_call.kwargs["extra"]["setup_configured"] is None + + @pytest.mark.asyncio + async def test_on_guild_join_logs_missing_permissions(self, bot_instance): + guild = MagicMock() + guild.id = 123456 + guild.name = "New Guild" + guild.member_count = 42 + guild.me = MagicMock() + guild.me.guild_permissions = guild_permissions(send_messages_in_threads=False) + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance.on_guild_join(guild) + + assert mock_logger.warning.call_args.args[0] == "Guild missing permissions" + + @pytest.mark.asyncio + async def test_on_guild_remove_logs_guild_metadata(self, bot_instance): + guild = MagicMock() + guild.id = 123456 + guild.name = "Old Guild" + guild.member_count = 5 + + with patch("typer_bot.bot.logger") as mock_logger: + await bot_instance.on_guild_remove(guild) + + info_call = mock_logger.info.call_args + assert info_call.args[0] == "Removed from guild" + assert info_call.kwargs["extra"] == { + "guild_id": 123456, + "guild_name": "Old Guild", + "member_count": 5, + } + + class TestFixtureAnnouncementSync: @pytest.fixture def bot_instance(self): diff --git a/typer_bot/bot.py b/typer_bot/bot.py index 63ebeed..b36689b 100644 --- a/typer_bot/bot.py +++ b/typer_bot/bot.py @@ -20,16 +20,11 @@ load_dotenv() -logger.info("=" * 50) -logger.info("STARTING TYPER BOT") -logger.info("=" * 50) - class TyperBot(commands.Bot): """Football predictions Discord bot.""" def __init__(self): - logger.info("Initializing TyperBot...") intents = discord.Intents.default() intents.message_content = True intents.members = True @@ -38,7 +33,6 @@ def __init__(self): self.db = Database() self.thread_handler = ThreadPredictionHandler(self, self.db) - logger.info("Database instance created") async def on_interaction(self, interaction: discord.Interaction): """Set trace ID and context for every interaction before processing.""" @@ -87,42 +81,34 @@ async def on_message_delete(self, message: discord.Message): async def setup_hook(self): """Initialize database and load cogs.""" - logger.info("Running setup_hook...") - try: await self.db.initialize() - logger.info("Database initialized successfully") + logger.info("Database initialized") await maybe_auto_seed_test_data(self.db.db_path) except Exception: logger.exception("Database initialization failed") raise - logger.info("Loading command cogs...") try: await self.load_extension("typer_bot.commands.user_commands") - logger.info("Loaded user_commands") except Exception: logger.exception("Failed to load user_commands") raise try: await self.load_extension("typer_bot.commands.admin_commands") - logger.info("Loaded admin_commands") except Exception: logger.exception("Failed to load admin_commands") raise - logger.info("Syncing slash commands...") try: synced = await self.tree.sync() logger.info(f"Synced {len(synced)} commands") except Exception: logger.exception("Failed to sync commands") - logger.info("Starting background tasks...") self.reminder_task.start() self._cleanup_sessions_task.start() - logger.info("Setup hook complete") async def on_ready(self): """Called when bot is ready.""" @@ -130,15 +116,45 @@ async def on_ready(self): logger.warning("Bot ready event fired before user was available") return - logger.info(f"✓ Bot connected: {self.user} (ID: {self.user.id})") - logger.info(f"✓ Connected to {len(self.guilds)} guild(s):") - for guild in self.guilds: - logger.info(f" - {guild.name} (ID: {guild.id})") + logger.info("Bot ready", extra={"bot_id": self.user.id, "guild_count": len(self.guilds)}) await self._check_permissions() await self._sync_fixture_thread() + async def on_guild_join(self, guild: discord.Guild): + """Log guild metadata and setup state when invited.""" + setup_configured = None + try: + config = await self.db.get_guild_config(str(guild.id)) + setup_configured = config is not None + except Exception: + logger.exception( + "Could not load guild setup state", + extra={"guild_id": guild.id, "guild_name": guild.name}, + ) + + logger.info( + "Joined guild", + extra={ + "guild_id": guild.id, + "guild_name": guild.name, + "member_count": guild.member_count, + "setup_configured": setup_configured, + }, + ) + await self._check_guild_permissions(guild) + + async def on_guild_remove(self, guild: discord.Guild): + logger.info( + "Removed from guild", + extra={ + "guild_id": guild.id, + "guild_name": guild.name, + "member_count": guild.member_count, + }, + ) + async def on_error(self, event_method, *_args, **_kwargs): """Handle uncaught errors.""" from typer_bot.utils.logger import get_log_context, get_trace_id @@ -261,18 +277,18 @@ async def _sync_fixture_thread(self): The stored message_id doubles as the thread_id since Discord public threads inherit their parent message's snowflake ID. """ - logger.info("Verifying fixture announcement...") - try: open_fixtures = await self.db.get_all_open_fixtures() if not open_fixtures: - logger.info("No open fixture found, skipping verification") + logger.debug("No open fixture found, skipping announcement verification") return for fixture in open_fixtures: message_id = fixture.get("message_id") if not message_id: - logger.info(f"Fixture {fixture['id']} has no message_id, skipping verification") + logger.debug( + f"Fixture {fixture['id']} has no message_id, skipping verification" + ) continue message = await self._find_fixture_announcement_message(fixture) @@ -283,9 +299,9 @@ async def _sync_fixture_thread(self): continue if message.thread: - logger.info(f"Fixture {fixture['id']} has thread {message.thread.id}") + logger.debug(f"Fixture {fixture['id']} has thread {message.thread.id}") else: - logger.info( + logger.warning( f"Fixture {fixture['id']} has no thread (/predict cannot post publicly)" ) @@ -410,55 +426,64 @@ async def _scan_fixture_message_in_guild(self, guild_id: str, message_id: str): return None - async def _check_permissions(self): - """Warn when a guild is missing permissions required for prediction workflows.""" + def _missing_guild_permissions(self, guild: discord.Guild) -> list[str] | None: required_permissions = [ ("send_messages", "Send Messages"), + ("send_messages_in_threads", "Send Messages in Threads"), ("read_message_history", "Read Message History"), ("add_reactions", "Add Reactions"), ("create_public_threads", "Create Public Threads"), ] - for guild in self.guilds: - me = guild.me - if not me: - logger.warning(f"Bot not found in guild {guild.name} (ID: {guild.id})") - continue + me = guild.me + if not me: + return None - missing = [] - for perm_attr, perm_name in required_permissions: - if not getattr(me.guild_permissions, perm_attr, False): - missing.append(perm_name) + return [ + perm_name + for perm_attr, perm_name in required_permissions + if not getattr(me.guild_permissions, perm_attr, False) + ] - if missing: - logger.warning( - f"⚠️ Guild '{guild.name}' (ID: {guild.id}): " - f"Missing permissions: {', '.join(missing)}" - ) - else: - logger.info(f"✓ Guild '{guild.name}': All required permissions present") + async def _check_guild_permissions(self, guild: discord.Guild) -> None: + missing = self._missing_guild_permissions(guild) + if missing is None: + logger.warning( + "Bot member not found in guild", + extra={"guild_id": guild.id, "guild_name": guild.name}, + ) + return + + if missing: + logger.warning( + "Guild missing permissions", + extra={ + "guild_id": guild.id, + "guild_name": guild.name, + "missing_permissions": ", ".join(missing), + }, + ) + + async def _check_permissions(self): + """Warn when a guild is missing permissions required for prediction workflows.""" + for guild in self.guilds: + await self._check_guild_permissions(guild) def main(): """Run the bot.""" - logger.info("Starting main()...") - token = os.getenv("DISCORD_TOKEN") if not token: - logger.error("❌ DISCORD_TOKEN environment variable not set!") - logger.error("Please set DISCORD_TOKEN in your deployment environment") + logger.error("DISCORD_TOKEN environment variable not set") sys.exit(1) if token == "your_bot_token_here": - logger.error("❌ DISCORD_TOKEN is set to placeholder value!") - logger.error("Please update it with your actual bot token") + logger.error("DISCORD_TOKEN is set to placeholder value") sys.exit(1) # The guard above exits on missing/placeholder tokens; this keeps the type checker honest. if token is None: raise RuntimeError("Token validation failed unexpectedly") - logger.info("✅ Token configured") - environment = os.getenv("ENVIRONMENT", "development") is_production = environment.lower() in ("production", "prod") @@ -467,23 +492,20 @@ def main(): else: logger.info("Running in non-production environment: %s", environment) - logger.info("Creating TyperBot instance...") - try: bot = TyperBot() - logger.info("Starting bot.run()...") bot.run(token, log_handler=None) except discord.PrivilegedIntentsRequired: logger.exception( - "❌ Privileged intents are not enabled in the Discord developer portal. " + "Privileged intents are not enabled in the Discord developer portal. " "Enable Message Content Intent and Server Members Intent for this bot application." ) sys.exit(1) except discord.LoginFailure: - logger.exception("❌ Discord login failed - check if DISCORD_TOKEN is valid") + logger.exception("Discord login failed; check DISCORD_TOKEN") sys.exit(1) except Exception: - logger.exception("❌ Unexpected error") + logger.exception("Unexpected bot startup error") sys.exit(1)