diff --git a/src/bot.py b/src/bot.py index 6f004f56..efe72d6a 100644 --- a/src/bot.py +++ b/src/bot.py @@ -1,5 +1,6 @@ import logging import socket +from typing import TypeVar import discord from aiohttp import AsyncResolver, ClientSession, TCPConnector @@ -27,7 +28,6 @@ UserInputError, ) from sqlalchemy.exc import NoResultFound -from typing import TypeVar from src import trace_config from src.core import constants, settings @@ -81,7 +81,7 @@ async def on_ready(self) -> None: try: await self.role_manager.reload() except Exception: - logger.warning("Failed to reload dynamic roles on reconnect, keeping previous cache", exc_info=True) + logger.warning("Failed to reload dynamic roles on reconnect, keeping previous cache") logger.info(f"Started bot as {name}") print("Loading ScheduledTasks cog...") @@ -136,14 +136,14 @@ async def on_application_command_error( elif isinstance(error, CommandOnCooldown): message = f"You are on cooldown. Try again in {error.retry_after:.2f}s" elif isinstance(error, NoResultFound): - message = f"The requested object could not be found." + message = "The requested object could not be found." errored_commands.labels(ctx.command.name).inc() if message is None: raise error else: - logger.debug(f"A user caused an error which was handled.", exc_info=error) + logger.debug("A user caused an error which was handled.", exc_info=error) await ctx.respond(message, delete_after=15, ephemeral=True) async def on_application_command_completion(self, ctx: ApplicationContext) -> None: @@ -200,25 +200,19 @@ async def get_member_or_user(self, guild: Guild, id_: int) -> Member | User | No """Get a member or a user from the guild or discord.""" try: return await guild.fetch_member(id_) - except Forbidden as exc: - logger.warning( - f"Unauthorized attempt to fetch member with id: {id_}", exc_info=exc - ) - except NotFound as exc: - logger.warning(f"Could not find guild member with id: {id_}", exc_info=exc) + except Forbidden: + logger.warning(f"Unauthorized attempt to fetch member with id: {id_}") + except NotFound: + logger.warning(f"Could not find guild member with id: {id_}") try: return await self.get_or_fetch_user(id_) - except Forbidden as exc: - logger.warning( - f"Unauthorized attempt to fetch member with id: {id_}", exc_info=exc - ) - except NotFound as exc: - logger.warning( - f"Could not find guild member with id: {id_}", exc_info=exc - ) + except Forbidden: + logger.warning(f"Unauthorized attempt to fetch user with id: {id_}") + except NotFound: + logger.warning(f"Could not find user with id: {id_}") except HTTPException as exc: logger.error( - f"Discord error while fetching guild member with id: {id_}", + f"Discord error while fetching user with id: {id_}", exc_info=exc, ) except HTTPException as exc: @@ -228,17 +222,13 @@ async def get_member_or_user(self, guild: Guild, id_: int) -> Member | User | No ) try: return await self.get_or_fetch_user(id_) - except Forbidden as exc: - logger.warning( - f"Unauthorized attempt to fetch member with id: {id_}", exc_info=exc - ) - except NotFound as exc: - logger.warning( - f"Could not find guild member with id: {id_}", exc_info=exc - ) + except Forbidden: + logger.warning(f"Unauthorized attempt to fetch user with id: {id_}") + except NotFound: + logger.warning(f"Could not find user with id: {id_}") except HTTPException as exc: logger.error( - f"Discord error while fetching guild member with id: {id_}", + f"Discord error while fetching user with id: {id_}", exc_info=exc, ) diff --git a/src/helpers/ban.py b/src/helpers/ban.py index 77954c71..bb46c0b0 100644 --- a/src/helpers/ban.py +++ b/src/helpers/ban.py @@ -6,16 +6,7 @@ from enum import Enum import discord -from discord import ( - Forbidden, - Guild, - HTTPException, - Member, - NotFound, - User, - TextChannel, - ClientUser, -) +from discord import ClientUser, Forbidden, Guild, HTTPException, Member, NotFound, TextChannel, User from sqlalchemy import select from sqlalchemy.exc import NoResultFound @@ -354,10 +345,9 @@ async def ban_member_with_epoch( # Try to actually ban the member from the guild try: await guild.ban(member, reason=reason, delete_message_seconds=0) - except Forbidden as exc: + except Forbidden: logger.warning( "Ban failed due to permission error", - exc_info=exc, extra={"ban_requestor": author.name, "ban_receiver": member.id}, ) if author: @@ -367,10 +357,8 @@ async def ban_member_with_epoch( code=BanCodes.FAILED, ) return - except HTTPException as ex: - logger.warning( - f"HTTPException when trying to ban user with ID {member.id}", exc_info=ex - ) + except HTTPException as exc: + logger.warning(f"HTTPException when trying to ban user with ID {member.id}: {exc}") if author: return SimpleResponse( message="Here's a 400 Bad Request for you. Just like when you tried to ask me out, last week.", @@ -473,16 +461,13 @@ async def _dm_banned_member( try: await member.send(message) return True - except Forbidden as ex: + except Forbidden: logger.warning( f"Could not DM member with id {member.id} due to privacy settings, however will still attempt to ban " - f"them...", - exc_info=ex, - ) - except HTTPException as ex: - logger.warning( - f"HTTPException when trying to unban user with ID {member.id}", exc_info=ex + f"them..." ) + except HTTPException as exc: + logger.warning(f"HTTPException when trying to DM user with ID {member.id} about their ban: {exc}") return False @@ -616,17 +601,11 @@ async def add_infraction( f"After a total value of 3, permanent exclusion from the server may be enforced.\n" f"Following is the reason given:\n>>> {reason}\n" ) - except Forbidden as ex: + except Forbidden: message = "Could not DM member due to privacy settings, however the infraction was still added." - logger.warning( - f"Forbidden, when trying to contact user with ID {member.id} about infraction.", - exc_info=ex, - ) - except HTTPException as ex: + logger.warning(f"Forbidden, when trying to contact user with ID {member.id} about infraction.") + except HTTPException as exc: message = "Here's a 400 Bad Request for you. Just like when you tried to ask me out, last week." - logger.warning( - f"HTTPException when trying to add infraction for user with ID {member.id}", - exc_info=ex, - ) + logger.warning(f"HTTPException when trying to add infraction for user with ID {member.id}: {exc}") return SimpleResponse(message=message, delete_after=None) diff --git a/src/services/role_manager.py b/src/services/role_manager.py index 07392ddd..7159a3fd 100644 --- a/src/services/role_manager.py +++ b/src/services/role_manager.py @@ -104,9 +104,9 @@ async def load(self) -> None: total = sum(len(v) for v in self._roles.values()) logger.info(f"Loaded {total} dynamic roles from database") - except Exception: + except Exception as exc: if self._loaded: - logger.warning("Failed to reload dynamic roles from DB, keeping previous cache", exc_info=True) + logger.warning(f"Failed to reload dynamic roles from DB, keeping previous cache: {exc}") else: logger.error("Failed to load dynamic roles from DB on first attempt", exc_info=True) raise diff --git a/tests/src/helpers/test_ban.py b/tests/src/helpers/test_ban.py index c8eae476..8e79c6ab 100644 --- a/tests/src/helpers/test_ban.py +++ b/tests/src/helpers/test_ban.py @@ -1,3 +1,4 @@ +import logging from datetime import datetime, timezone from unittest import mock from unittest.mock import AsyncMock, MagicMock, patch @@ -5,7 +6,7 @@ import pytest from discord import Forbidden, HTTPException -from src.helpers.ban import EVIDENCE_REQUIRED_MESSAGE, _check_member, _dm_banned_member, ban_member +from src.helpers.ban import EVIDENCE_REQUIRED_MESSAGE, _check_member, _dm_banned_member, add_infraction, ban_member from src.helpers.responses import SimpleResponse from tests import helpers @@ -277,3 +278,64 @@ async def test_ban_self(self, ctx, bot, guild): assert isinstance(response, SimpleResponse) assert response.message == "You cannot ban yourself." + + +def _http_exception() -> HTTPException: + response = MagicMock(status=500, reason="Internal Server Error") + return HTTPException(response, {"code": 0, "message": "Something broke"}) + + +HTTP_EXCEPTION_TEXT = "500 Internal Server Error (error code: 0): Something broke" + + +@pytest.fixture +def ban_logs(caplog, monkeypatch): + # The alembic migration tests call logging.config.fileConfig, which disables existing loggers. + monkeypatch.setattr(logging.getLogger("src.helpers.ban"), "disabled", False) + caplog.set_level(logging.DEBUG, logger="src.helpers.ban") + + def warnings() -> list[logging.LogRecord]: + return [r for r in caplog.records if r.name == "src.helpers.ban" and r.levelno == logging.WARNING] + + return warnings + + +class TestHttpExceptionWarnings: + @pytest.mark.asyncio + async def test_failed_ban_logs_the_cause(self, bot, guild, member, ban_logs): + future_timestamp = int(datetime.now(tz=timezone.utc).timestamp() + 86400) + guild.ban = AsyncMock(side_effect=_http_exception()) + with ( + mock.patch("src.helpers.ban._check_member", return_value=None), + mock.patch("src.helpers.ban._dm_banned_member", return_value=True), + mock.patch("src.helpers.ban._get_ban_or_create", return_value=(1, False)), + mock.patch("src.helpers.ban.validate_duration", return_value=(future_timestamp, "")), + ): + await ban_member(bot, guild, member, "1d", "reason", "evidence") + + assert [r.getMessage() for r in ban_logs()] == [ + f"HTTPException when trying to ban user with ID {member.id}: {HTTP_EXCEPTION_TEXT}" + ] + assert ban_logs()[0].exc_info is None + + @pytest.mark.asyncio + async def test_failed_ban_dm_logs_the_cause(self, guild, member, ban_logs): + member.send = AsyncMock(side_effect=_http_exception()) + result = await _dm_banned_member("2023-05-19", guild, member, "reason") + + assert result is False + assert [r.getMessage() for r in ban_logs()] == [ + f"HTTPException when trying to DM user with ID {member.id} about their ban: {HTTP_EXCEPTION_TEXT}" + ] + assert ban_logs()[0].exc_info is None + + @pytest.mark.asyncio + async def test_failed_infraction_dm_logs_the_cause(self, guild, member, ban_logs): + member.send = AsyncMock(side_effect=_http_exception()) + with mock.patch("src.helpers.ban.AsyncSessionLocal"): + await add_infraction(guild, member, 1, "reason", helpers.MockMember()) + + assert [r.getMessage() for r in ban_logs()] == [ + f"HTTPException when trying to add infraction for user with ID {member.id}: {HTTP_EXCEPTION_TEXT}" + ] + assert ban_logs()[0].exc_info is None diff --git a/tests/src/services/__init__.py b/tests/src/services/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/tests/src/services/test_role_manager.py b/tests/src/services/test_role_manager.py new file mode 100644 index 00000000..0e121b29 --- /dev/null +++ b/tests/src/services/test_role_manager.py @@ -0,0 +1,32 @@ +import logging +from unittest.mock import patch + +import pytest + +from src.services.role_manager import RoleManager + + +@pytest.fixture(autouse=True) +def enabled_role_manager_logger(monkeypatch): + # The alembic migration tests call logging.config.fileConfig, which disables existing loggers. + monkeypatch.setattr(logging.getLogger("src.services.role_manager"), "disabled", False) + + +class TestLoad: + @pytest.mark.asyncio + async def test_failed_reload_keeps_cache_and_logs_the_cause_without_traceback(self, caplog): + manager = RoleManager() + manager._loaded = True + with ( + patch("src.services.role_manager.AsyncSessionLocal", side_effect=RuntimeError("database is down")), + caplog.at_level(logging.DEBUG, logger="src.services.role_manager"), + ): + await manager.load() + + records = [r for r in caplog.records if r.name == "src.services.role_manager"] + assert len(records) == 1 + assert records[0].levelno == logging.WARNING + assert records[0].getMessage() == ( + "Failed to reload dynamic roles from DB, keeping previous cache: database is down" + ) + assert records[0].exc_info is None diff --git a/tests/src/test_bot.py b/tests/src/test_bot.py new file mode 100644 index 00000000..9eceb59d --- /dev/null +++ b/tests/src/test_bot.py @@ -0,0 +1,157 @@ +import logging +from unittest.mock import AsyncMock, MagicMock + +import pytest +from discord import Forbidden, HTTPException, NotFound + +from src.bot import Bot + +USER_ID = 123456789 + + +@pytest.fixture(autouse=True) +def enabled_bot_logger(monkeypatch): + # The alembic migration tests call logging.config.fileConfig, which disables existing loggers. + monkeypatch.setattr(logging.getLogger("src.bot"), "disabled", False) + + +def _response(status: int) -> MagicMock: + response = MagicMock() + response.status = status + response.reason = "reason" + return response + + +def _bot(fetch_member_error: Exception | None = None, user_result=None) -> MagicMock: + bot = MagicMock() + bot.guild = MagicMock() + bot.guild.fetch_member = AsyncMock(side_effect=fetch_member_error, return_value="member") + if isinstance(user_result, Exception): + bot.get_or_fetch_user = AsyncMock(side_effect=user_result) + else: + bot.get_or_fetch_user = AsyncMock(return_value=user_result) + return bot + + +def _records(caplog): + return [r for r in caplog.records if r.name == "src.bot"] + + +class TestGetMemberOrUser: + @pytest.mark.asyncio + async def test_returns_member(self, caplog): + bot = _bot() + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result == "member" + assert _records(caplog) == [] + + @pytest.mark.asyncio + async def test_member_not_in_guild_falls_back_to_user_without_traceback(self, caplog): + bot = _bot(NotFound(_response(404), "Unknown Member"), user_result="user") + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result == "user" + bot.get_or_fetch_user.assert_awaited_once_with(USER_ID) + records = _records(caplog) + assert len(records) == 1 + assert records[0].levelno == logging.WARNING + assert records[0].getMessage() == f"Could not find guild member with id: {USER_ID}" + assert records[0].exc_info is None + + @pytest.mark.asyncio + async def test_member_and_user_not_found_logs_warnings_without_traceback(self, caplog): + user_error = NotFound(_response(404), "Unknown User") + bot = _bot(NotFound(_response(404), "Unknown Member"), user_result=user_error) + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result is None + warnings = [r for r in _records(caplog) if r.levelno == logging.WARNING] + assert len(warnings) == 2 + assert warnings[0].getMessage() == f"Could not find guild member with id: {USER_ID}" + assert warnings[0].exc_info is None + assert warnings[1].getMessage() == f"Could not find user with id: {USER_ID}" + assert warnings[1].exc_info is None + + @pytest.mark.asyncio + async def test_forbidden_fetching_member_logs_warning_without_traceback(self, caplog): + error = Forbidden(_response(403), "Missing Access") + bot = _bot(error) + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result is None + bot.get_or_fetch_user.assert_not_awaited() + records = _records(caplog) + assert len(records) == 1 + assert records[0].levelno == logging.WARNING + assert records[0].getMessage() == f"Unauthorized attempt to fetch member with id: {USER_ID}" + assert records[0].exc_info is None + + @pytest.mark.asyncio + async def test_forbidden_fetching_user_after_member_not_found_logs_warnings_without_traceback(self, caplog): + error = Forbidden(_response(403), "Missing Access") + bot = _bot(NotFound(_response(404), "Unknown Member"), user_result=error) + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result is None + warnings = [r for r in _records(caplog) if r.levelno == logging.WARNING] + assert len(warnings) == 2 + assert warnings[0].getMessage() == f"Could not find guild member with id: {USER_ID}" + assert warnings[0].exc_info is None + assert warnings[1].getMessage() == f"Unauthorized attempt to fetch user with id: {USER_ID}" + assert warnings[1].exc_info is None + + @pytest.mark.asyncio + async def test_http_error_after_member_not_found_logs_error_with_traceback(self, caplog): + error = HTTPException(_response(500), "boom") + bot = _bot(NotFound(_response(404), "Unknown Member"), user_result=error) + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result is None + errors = [r for r in _records(caplog) if r.levelno == logging.ERROR] + assert len(errors) == 1 + assert errors[0].getMessage() == f"Discord error while fetching user with id: {USER_ID}" + assert errors[0].exc_info[1] is error + + @pytest.mark.asyncio + async def test_http_error_fetching_member_falls_back_to_user(self, caplog): + error = HTTPException(_response(500), "boom") + bot = _bot(error, user_result="user") + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result == "user" + records = _records(caplog) + assert len(records) == 1 + assert records[0].levelno == logging.ERROR + assert records[0].getMessage() == f"Discord error while fetching guild member with id: {USER_ID}" + assert records[0].exc_info[1] is error + + @pytest.mark.asyncio + @pytest.mark.parametrize( + ("user_error", "level", "message"), + [ + (Forbidden(_response(403), "Missing Access"), logging.WARNING, + f"Unauthorized attempt to fetch user with id: {USER_ID}"), + (NotFound(_response(404), "Unknown User"), logging.WARNING, + f"Could not find user with id: {USER_ID}"), + (HTTPException(_response(500), "boom"), logging.ERROR, + f"Discord error while fetching user with id: {USER_ID}"), + ], + ) + async def test_user_fallback_after_http_error_logs_user_wording(self, caplog, user_error, level, message): + bot = _bot(HTTPException(_response(500), "boom"), user_result=user_error) + with caplog.at_level(logging.DEBUG, logger="src.bot"): + result = await Bot.get_member_or_user(bot, bot.guild, USER_ID) + + assert result is None + records = _records(caplog) + assert len(records) == 2 + assert records[1].levelno == level + assert records[1].getMessage() == message diff --git a/tests/src/test_logging_rules.py b/tests/src/test_logging_rules.py new file mode 100644 index 00000000..59e18f10 --- /dev/null +++ b/tests/src/test_logging_rules.py @@ -0,0 +1,22 @@ +import ast +from pathlib import Path + +SRC = Path(__file__).resolve().parents[2] / "src" + + +def _warnings_with_traceback() -> list[str]: + found = [] + for path in sorted(SRC.rglob("*.py")): + for node in ast.walk(ast.parse(path.read_text())): + if ( + isinstance(node, ast.Call) + and isinstance(node.func, ast.Attribute) + and node.func.attr == "warning" + and any(kw.arg in ("exc_info", "stack_info") for kw in node.keywords) + ): + found.append(f"{path.relative_to(SRC.parent)}:{node.lineno}") + return found + + +def test_warnings_do_not_log_a_traceback(): + assert _warnings_with_traceback() == []