Add logging

.env.template

@@ -1,3 +1,5 @@
 DISCORD_BOT_TOKEN=
 DISCORD_CMD_PREFIX=
+DISCORD_LOG_CHANNEL_ID=
+DISCORD_LOG_CHANNEL_CLEAR_ON_STARTUP=False
 YOUTUBE_COOKIES=youtube.com_cookies.txt

src/bot.py

@@ -2,6 +2,8 @@ import os
 import sys
 import asyncio
 from dataclasses import dataclass
+from distutils.util import strtobool
+import logging
 
 import discord
 from discord.ext import commands, tasks
@@ -10,6 +12,7 @@ import youtube_dl
 
 from error import ErrorHandler
 from message import NowPlayingMessage, QueuedMessage, ErrorMessage
+from log import create_logger, DiscordLogger
 
 load_dotenv()
 
@@ -25,7 +28,7 @@ class Song:
 
 
 class Music(commands.Cog):
-  def __init__(self, bot):
+  def __init__(self, bot: commands.Bot, logger: logging.Logger):
     self._bot = bot
     self._queue = asyncio.Queue()
     self._queue_lock = asyncio.Lock()
@@ -52,6 +55,15 @@ class Music(commands.Cog):
     # pylint: disable=no-member
     self._handle_playback.start()
 
+    self.logger = logger
+    if log_channel_id := os.environ.get("DISCORD_LOG_CHANNEL_ID", None):
+      clear_on_startup = os.environ.get("DISCORD_LOG_CHANNEL_CLEAR_ON_STARTUP", False)
+      if clear_on_startup == "":
+        clear_on_startup = False
+      if isinstance(clear_on_startup, str):
+        clear_on_startup = bool(strtobool(clear_on_startup))
+      self.logger.addHandler(DiscordLogger(self._bot, channel_id=log_channel_id, clear_on_startup=clear_on_startup))
+
   def cog_unload(self):
     # pylint: disable=no-member
     self._handle_playback.cancel()
@@ -79,7 +91,7 @@ class Music(commands.Cog):
 
         def after(err):
           if err:
-            print(f"Player error: {err}")
+            self.logger.error(f"Player error: {err}")
           self._next()
         ctx.voice_client.play(audio, after=after)
         embed = NowPlayingMessage(title=song.title, url=song.webpage_url)
@@ -87,7 +99,7 @@ class Music(commands.Cog):
         await self._add_skip_button(msg)
       # pylint: disable=broad-except
       except Exception as err:
-        print(f"Error during playback: {err}")
+        self.logger.error(f"Error during playback: {err}")
         if ctx:
           embed = ErrorMessage(str(err))
           await ctx.send(embed=embed)
@@ -154,20 +166,21 @@ class Music(commands.Cog):
 
 if __name__ == "__main__":
   prefix = os.environ.get("DISCORD_CMD_PREFIX", "!")
+  logger = create_logger("bot")
   bot = commands.Bot(command_prefix=commands.when_mentioned_or(prefix),
                      description='Relatively simple music bot example')
 
   @bot.event
   async def on_ready():
-    print(f"Logged in as {bot.user} ({bot.user.id})")
+    logger.info(f"Logged in as {bot.user} ({bot.user.id})")
-    print('------')
+    logger.info('------')
 
-  bot.add_cog(Music(bot))
+  bot.add_cog(Music(bot, logger=logger))
-  bot.add_cog(ErrorHandler(bot))
+  bot.add_cog(ErrorHandler(bot, logger=logger))
 
   token = os.environ.get("DISCORD_BOT_TOKEN", None)
   if not token:
-    print("Discord bot token not found")
+    logger.warning("Discord bot token not found")
     sys.exit(1)
 
   bot.run(token)

src/error.py

@@ -1,3 +1,5 @@
+import logging
+
 from discord.ext import commands
 
 from message import ErrorMessage
@@ -6,8 +8,9 @@ from message import ErrorMessage
 class ErrorHandler(commands.Cog):
   """A cog for global error handling."""
 
-  def __init__(self, bot: commands.Bot):
+  def __init__(self, bot: commands.Bot, logger: logging.Logger):
     self.bot = bot
+    self.logger = logger
 
   @commands.Cog.listener()
   async def on_command_error(self, ctx: commands.Context, error: commands.CommandError):

src/log.py

@@ -0,0 +1,66 @@
+import asyncio
+import logging
+from logging import LogRecord
+import sys
+import os
+from datetime import datetime
+
+from discord import TextChannel
+from discord.ext.commands import Bot as DiscordBot
+
+
+__LOG_FORMAT__ = '%(asctime)s %(name)-5s %(levelname)-8s %(message)s'
+__DATE_FORMAT__ = '%Y-%m-%d %H:%M:%S'
+
+
+def create_logger(name: str) -> logging.Logger:
+  """Create logger with some sane defaults."""
+  logger = logging.getLogger(name)
+  logger.setLevel(logging.DEBUG)
+
+  stream_handler = logging.StreamHandler(stream=sys.stdout)
+
+  COMMIT = os.getenv('GIT_COMMIT') or 'no-commit'
+  timestamp = datetime.now().strftime("%Y-%m-%dT%H:%M:%S")
+  log_path = "%s_%s.log" % (COMMIT, timestamp)
+
+  file_handler = logging.FileHandler(log_path)
+
+  formatter = logging.Formatter(
+      fmt='%(asctime)s %(name)-5s %(levelname)-8s %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
+  stream_handler.setFormatter(formatter)
+  file_handler.setFormatter(formatter)
+
+  logger.addHandler(stream_handler)
+  logger.addHandler(file_handler)
+
+  return logger
+
+
+class DiscordLogger(logging.Handler):
+  """Logging handler which sends logs to the specified discord channel."""
+
+  def __init__(self, bot: DiscordBot, channel_id=None, clear_on_startup=False):
+    super().__init__()
+    self._bot = bot
+    self._channel_id = channel_id
+    self._channel: TextChannel = None
+    self._channel_cleared = False
+    self._clear_on_startup = clear_on_startup
+    self._formatter = logging.Formatter(fmt='%(asctime)s %(name)-5s %(levelname)-8s %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
+
+  def emit(self, record: LogRecord) -> None:
+    if self._channel_id is not None:
+      msg = self._formatter.format(record)
+
+      async def _emit_to_channel() -> None:
+        if self._channel is None:
+          self._channel = await self._bot.fetch_channel(self._channel_id)
+          if self._clear_on_startup:
+            async for log in self._channel.history(limit=None):
+              await log.delete()
+
+        if self._channel is not None:
+          await self._channel.send(msg)
+
+      asyncio.create_task(_emit_to_channel())

test/conftest.py

@@ -2,6 +2,8 @@ import asyncio
 import sys
 from pathlib import Path
 from unittest.mock import Mock
+import glob
+import os
 
 import pytest
 from pytest_mock import MockerFixture
@@ -13,6 +15,14 @@ sys.path.insert(0, SRC_PATH)
 from bot import Music
 
 
+@pytest.fixture(scope="session", autouse=True)
+def start_xvfb_server(request):
+  yield
+  logs = glob.glob('*.log')
+  for log in logs:
+    os.remove(log)
+
+
 @pytest.fixture
 def bot(mocker: MockerFixture):
   bot_mock = mocker.patch('discord.ext.commands.Bot', autospec=True)