Merge branch '21-add-more-logging' into 'develop'

Resolve "Add more logging"

Closes #21

See merge request ekzyis/musicube!21

src/bot.py

@@ -70,6 +70,7 @@ class Music(commands.Cog):
 
   def _next(self):
     """Trigger playback of next song."""
+    self.logger.info("Song finished. Triggering playback of next song")
     self._queue.task_done()
     self._current_skip_message = None
     if self._queue_lock.locked():
@@ -79,12 +80,16 @@ class Music(commands.Cog):
   async def _handle_playback(self):
     while True:
       try:
+        self.logger.info("Waiting for queue lock to acquire ...")
         await self._queue_lock.acquire()
+        self.logger.info("Queue lock acquired! Waiting for song queue to return a song ...")
         ctx, song = await self._queue.get()
+        self.logger.info("Queue returned a song!")
         if ctx.voice_client is None:
           # Bot is no longer in a voice channel.
           # This could be the case because a stop command was issued.
           # We will skip this (and possibly all remaining songs) in the queue
+          self.logger.info('Bot is no longer in a voice channel. Skipping song "%s"', song.title)
           self._next()
           continue
         audio = discord.FFmpegPCMAudio(song.audio_url, **self._ffmpeg_options)
@@ -93,6 +98,7 @@ class Music(commands.Cog):
           if err:
             self.logger.error("Player error: %s", err)
           self._next()
+        self.logger.info('Now playing song "%s"', song.title)
         ctx.voice_client.play(audio, after=after)
         embed = NowPlayingMessage(title=song.title, url=song.webpage_url)
         msg = await ctx.send(embed=embed)
@@ -133,6 +139,7 @@ class Music(commands.Cog):
             audio_url=data.get('url'),
             webpage_url=data.get('webpage_url')
         )
+        self.logger.info('Qeueing song: title="%s", audio_url=%s, webpage_url=%s', song.title, song.audio_url, song.webpage_url)
         await self._queue.put((ctx, song))
         if ctx.voice_client.is_playing():
           embed = QueuedMessage(title=song.title, url=song.webpage_url)
@@ -144,6 +151,7 @@ class Music(commands.Cog):
       raise commands.CommandError("No song playing")
     # This skips to next song because the bot does not differentiate between
     # a song stopping because it is finished or because it was manually stopped.
+    self.logger.info("Skipping song")
     voice_client.stop()
 
   @commands.command()
@@ -153,13 +161,16 @@ class Music(commands.Cog):
 
   @commands.command()
   async def stop(self, ctx):
+    self.logger.info("Stopping playback")
     await ctx.voice_client.disconnect()
 
   @play.before_invoke
   async def ensure_voice(self, ctx):
     if ctx.voice_client is None:
       if ctx.author.voice:
+        self.logger.info("Connecting to voice channel ...")
         await ctx.author.voice.channel.connect()
+        self.logger.info("Connected")
       else:
         raise commands.CommandError("Author not connected to a voice channel")
 

src/error.py

@@ -14,7 +14,9 @@ class ErrorHandler(commands.Cog):
 
   @commands.Cog.listener()
   async def on_command_error(self, ctx: commands.Context, error: commands.CommandError):
+    command_name = ctx.command.name
     if isinstance(error, commands.CommandNotFound):
+      self.logger.error(error)
       return
     if isinstance(error, commands.MissingPermissions):
       message = "You are missing the required permissions to run this command!"
@@ -25,6 +27,7 @@ class ErrorHandler(commands.Cog):
     else:
       message = "Oh no! Something went wrong while running the command!"
 
+    self.logger.error('Error during command "%s": %s', command_name, message)
     embed = ErrorMessage(message)
     await ctx.send(embed=embed)