Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions Pipfile
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ deepdiff = "~=4.0"
requests = "~=2.22"
more_itertools = "~=7.2"
urllib3 = ">=1.24.2,<1.25"
sentry-sdk = "~=0.14"

[dev-packages]
coverage = "~=4.5"
Expand Down
10 changes: 9 additions & 1 deletion Pipfile.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 1 addition & 1 deletion azure-pipelines.yml
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ jobs:
- script: python -m flake8
displayName: 'Run linter'

- script: BOT_API_KEY=foo BOT_TOKEN=bar WOLFRAM_API_KEY=baz REDDIT_CLIENT_ID=spam REDDIT_SECRET=ham coverage run -m xmlrunner
- script: BOT_API_KEY=foo BOT_SENTRY_DSN=blah BOT_TOKEN=bar WOLFRAM_API_KEY=baz REDDIT_CLIENT_ID=spam REDDIT_SECRET=ham coverage run -m xmlrunner
displayName: Run tests

- script: coverage report -m && coverage xml -o coverage.xml
Expand Down
4 changes: 4 additions & 0 deletions bot/__main__.py
Original file line number Diff line number Diff line change
@@ -1,10 +1,14 @@
import discord
import sentry_sdk
from discord.ext.commands import when_mentioned_or

from bot import patches
from bot.bot import Bot
from bot.constants import Bot as BotConfig, DEBUG_MODE

sentry_sdk.init(
dsn=BotConfig.sentry_dsn
)

bot = Bot(
command_prefix=when_mentioned_or(BotConfig.prefix),
Expand Down
74 changes: 0 additions & 74 deletions bot/api.py
Original file line number Diff line number Diff line change
Expand Up @@ -141,77 +141,3 @@ def loop_is_running() -> bool:
except RuntimeError:
return False
return True


class APILoggingHandler(logging.StreamHandler):
"""Site API logging handler."""

def __init__(self, client: APIClient):
logging.StreamHandler.__init__(self)
self.client = client

# internal batch of shipoff tasks that must not be scheduled
# on the event loop yet - scheduled when the event loop is ready.
self.queue = []

async def ship_off(self, payload: dict) -> None:
"""Ship log payload to the logging API."""
try:
await self.client.post('logs', json=payload)
except ResponseCodeError as err:
log.warning(
"Cannot send logging record to the site, got code %d.",
err.response.status,
extra={'via_handler': True}
)
except Exception as err:
log.warning(
"Cannot send logging record to the site: %r",
err,
extra={'via_handler': True}
)

def emit(self, record: logging.LogRecord) -> None:
"""
Determine if a log record should be shipped to the logging API.

If the asyncio event loop is not yet running, log records will instead be put in a queue
which will be consumed once the event loop is running.

The following two conditions are set:
1. Do not log anything below DEBUG (only applies to the monkeypatched `TRACE` level)
2. Ignore log records originating from this logging handler itself to prevent infinite recursion
"""
if (
record.levelno >= logging.DEBUG
and not record.__dict__.get('via_handler')
):
payload = {
'application': 'bot',
'logger_name': record.name,
'level': record.levelname.lower(),
'module': record.module,
'line': record.lineno,
'message': self.format(record)
}

task = self.ship_off(payload)
if not loop_is_running():
self.queue.append(task)
else:
asyncio.create_task(task)
self.schedule_queued_tasks()

def schedule_queued_tasks(self) -> None:
"""Consume the queue and schedule the logging of each queued record."""
for task in self.queue:
asyncio.create_task(task)

if self.queue:
log.debug(
"Scheduled %d pending logging tasks.",
len(self.queue),
extra={'via_handler': True}
)

self.queue.clear()
2 changes: 0 additions & 2 deletions bot/bot.py
Original file line number Diff line number Diff line change
Expand Up @@ -27,8 +27,6 @@ def __init__(self, *args, **kwargs):
self.http_session: Optional[aiohttp.ClientSession] = None
self.api_client = api.APIClient(loop=self.loop, connector=self.connector)

log.addHandler(api.APILoggingHandler(self.api_client))

def add_cog(self, cog: commands.Cog) -> None:
"""Adds a "cog" to the bot and logs the operation."""
super().add_cog(cog)
Expand Down
25 changes: 21 additions & 4 deletions bot/cogs/error_handler.py
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
UserInputError,
)
from discord.ext.commands import Cog, Context
from sentry_sdk import push_scope

from bot.api import ResponseCodeError
from bot.bot import Bot
Expand Down Expand Up @@ -147,10 +148,26 @@ async def handle_unexpected_error(ctx: Context, e: CommandError) -> None:
f"Sorry, an unexpected error occurred. Please let us know!\n\n"
f"```{e.__class__.__name__}: {e}```"
)
log.error(
f"Error executing command invoked by {ctx.message.author}: {ctx.message.content}"
)
raise e
Comment thread
MarkKoz marked this conversation as resolved.

with push_scope() as scope:
scope.user = {
"id": ctx.author.id,
"username": str(ctx.author)
}

scope.set_tag("command", ctx.command.qualified_name)
scope.set_tag("message_id", ctx.message.id)
scope.set_tag("channel_id", ctx.channel.id)

scope.set_extra("full_message", ctx.message.content)

if ctx.guild is not None:
scope.set_extra(
"jump_to",
f"https://discordapp.com/channels/{ctx.guild.id}/{ctx.channel.id}/{ctx.message.id}"
)

log.error(f"Error executing command invoked by {ctx.message.author}: {ctx.message.content}", exc_info=e)


def setup(bot: Bot) -> None:
Expand Down
2 changes: 1 addition & 1 deletion bot/constants.py
Original file line number Diff line number Diff line change
Expand Up @@ -193,7 +193,7 @@ class Bot(metaclass=YAMLGetter):

prefix: str
token: str

sentry_dsn: str

class Filter(metaclass=YAMLGetter):
section = "filter"
Expand Down
1 change: 1 addition & 0 deletions config-default.yml
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
bot:
prefix: "!"
token: !ENV "BOT_TOKEN"
sentry_dsn: !ENV "BOT_SENTRY_DSN"

cooldowns:
# Per channel, per tag.
Expand Down
64 changes: 2 additions & 62 deletions tests/bot/test_api.py
Original file line number Diff line number Diff line change
@@ -1,9 +1,7 @@
import logging
import unittest
from unittest.mock import MagicMock, patch
from unittest.mock import MagicMock

from bot import api
from tests.base import LoggingTestCase
from tests.helpers import async_test


Expand Down Expand Up @@ -34,7 +32,7 @@ def test_response_code_error_default_initialization(self):
self.assertEqual(error.response_text, "")
self.assertIs(error.response, self.error_api_response)

def test_responde_code_error_string_representation_default_initialization(self):
def test_response_code_error_string_representation_default_initialization(self):
"""Test the string representation of `ResponseCodeError` initialized without text or json."""
error = api.ResponseCodeError(response=self.error_api_response)
self.assertEqual(str(error), f"Status: {self.error_api_response.status} Response: ")
Expand Down Expand Up @@ -76,61 +74,3 @@ def test_response_code_error_string_representation_with_nonempty_response_text(s
response_text=text_data
)
self.assertEqual(str(error), f"Status: {self.error_api_response.status} Response: {text_data}")


class LoggingHandlerTests(LoggingTestCase):
"""Tests the bot's API Log Handler."""

@classmethod
def setUpClass(cls):
cls.debug_log_record = logging.LogRecord(
name='my.logger', level=logging.DEBUG,
pathname='my/logger.py', lineno=666,
msg="Lemon wins", args=(),
exc_info=None
)

cls.trace_log_record = logging.LogRecord(
name='my.logger', level=logging.TRACE,
pathname='my/logger.py', lineno=666,
msg="This will not be logged", args=(),
exc_info=None
)

def setUp(self):
self.log_handler = api.APILoggingHandler(None)

def test_emit_appends_to_queue_with_stopped_event_loop(self):
"""Test if `APILoggingHandler.emit` appends to queue when the event loop is not running."""
with patch("bot.api.APILoggingHandler.ship_off") as ship_off:
# Patch `ship_off` to ease testing against the return value of this coroutine.
ship_off.return_value = 42
self.log_handler.emit(self.debug_log_record)

self.assertListEqual(self.log_handler.queue, [42])

def test_emit_ignores_less_than_debug(self):
"""`APILoggingHandler.emit` should not queue logs with a log level lower than DEBUG."""
self.log_handler.emit(self.trace_log_record)
self.assertListEqual(self.log_handler.queue, [])

def test_schedule_queued_tasks_for_empty_queue(self):
"""`APILoggingHandler` should not schedule anything when the queue is empty."""
with self.assertNotLogs(level=logging.DEBUG):
self.log_handler.schedule_queued_tasks()

def test_schedule_queued_tasks_for_nonempty_queue(self):
"""`APILoggingHandler` should schedule logs when the queue is not empty."""
log = logging.getLogger("bot.api")

with self.assertLogs(logger=log, level=logging.DEBUG) as logs, patch('asyncio.create_task') as create_task:
self.log_handler.queue = [555]
self.log_handler.schedule_queued_tasks()
self.assertListEqual(self.log_handler.queue, [])
create_task.assert_called_once_with(555)

[record] = logs.records
self.assertEqual(record.message, "Scheduled 1 pending logging tasks.")
self.assertEqual(record.levelno, logging.DEBUG)
self.assertEqual(record.name, 'bot.api')
self.assertIn('via_handler', record.__dict__)