From d31cab9ffd0083143165a459b1fea9a4b2676e6f Mon Sep 17 00:00:00 2001
From: Ev-1 <33662061+Ev-1@users.noreply.github.com>
Date: Sun, 9 Oct 2022 10:00:00 +0200
Subject: [PATCH] Add lots of info and debug log. Update error handling

---
 bot.py                                        |   2 +-
 musicbot/cogs/errors.py                       |  16 +-
 musicbot/cogs/music/__init__.py               | 152 ++++++++++--------
 musicbot/cogs/music/decorators.py             |   4 +-
 musicbot/cogs/nodemanager.py                  |   6 +-
 musicbot/utils/mixplayer/mixqueue.py          |  39 +++--
 musicbot/utils/mixplayer/player.py            |  89 ++++++----
 musicbot/utils/mixplayer/test_queue.py        |   4 +-
 .../paginators/queuepaginator.py              |   2 +-
 9 files changed, 188 insertions(+), 126 deletions(-)

diff --git a/bot.py b/bot.py
index 70d1351..4647ddf 100644
--- a/bot.py
+++ b/bot.py
@@ -106,7 +106,7 @@ class Bot(commands.Bot):
         except Exception as e:
             tb = e.__traceback__
             traceback.print_tb(tb)
-            self.logger.error(e)
+            self.logger.exception(e)
 
 
 def run_bot(datadir, debug: bool = False):
diff --git a/musicbot/cogs/errors.py b/musicbot/cogs/errors.py
index 54b06b6..453e56a 100644
--- a/musicbot/cogs/errors.py
+++ b/musicbot/cogs/errors.py
@@ -2,7 +2,7 @@
 import discord
 from discord.ext import commands
 
-import traceback
+import sys
 
 from ..utils.userinteraction import ClearOn, Scroller
 from .helpformatter import commandhelper
@@ -62,6 +62,13 @@ class Errors(commands.Cog):
             elif (err.original == 'The channel is currently full'):
                 return await send_error_embed('{errors.full_channel}')
 
+        # Regular command invoke errors
+        if isinstance(err, commands.UserInputError):
+            if self.bot.debug:
+                self.logger.debug("User input error")
+                self.logger.debug(err)
+            return
+
         if isinstance(err, WrongVoiceChannelError):
             if (err.original.startswith("You need to be in my voice channel")):
                 return await send_error_embed(err.channels[0].name, title='{errors.my_channel}')
@@ -103,16 +110,15 @@ class Errors(commands.Cog):
         else:
             # Log all exceptions if the bot is in debug mode
             if self.bot.debug:
-                tb = err.__traceback__
-                traceback.print_tb(tb)
-                self.logger.debug("Error running command: %s\nTraceback: %s" % (ctx.command, err))
+                self.logger.error("Got error in command %s" % ctx.command)
+                self.logger.exception(err.with_traceback(sys.exc_info()[2]))
 
             else:
                 to_log = (RuntimeError, commands.CheckFailure, commands.CommandInvokeError,
                           commands.NoPrivateMessage)
 
                 if isinstance(err, to_log):
-                    self.logger.debug("Error running command: %s\nTraceback: %s" % (ctx.command, err))
+                    self.logger.info("Error running command: %s\nTraceback: %s" % (ctx.command, err))
 
 
 async def setup(bot):
diff --git a/musicbot/cogs/music/__init__.py b/musicbot/cogs/music/__init__.py
index 7981ef9..0a06ef4 100644
--- a/musicbot/cogs/music/__init__.py
+++ b/musicbot/cogs/music/__init__.py
@@ -9,8 +9,8 @@ from lavalink.models import AudioTrack
 import asyncio
 import json
 import re
-import urllib
-from typing import List
+import urllib.parse as urlparse
+from typing import List, Optional
 
 from bs4 import BeautifulSoup
 
@@ -49,10 +49,11 @@ class Music(commands.Cog):
     async def cog_before_invoke(self, ctx):
         """ Ensures a valid player exists whenever a command is run """
         # Creates a new only if one doesn't exist, ensures a valid player for all checks.
-        self.bot.lavalink.player_manager.create(ctx.guild.id)
+        if ctx.guild:
+            self.bot.lavalink.player_manager.create(ctx.guild.id)
 
     async def enqueue(self, ctx, track, embed, silent=False, check_max_length=True) -> tuple[discord.Embed, bool]:
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         # Only add tracks that don't exceed the max track length
         if maxlength := self.max_track_length(ctx.guild, player):
@@ -70,7 +71,7 @@ class Music(commands.Cog):
         track.requester = ctx.author.id
 
         # Add to player
-        track, pos_global, pos_local = player.add(requester=ctx.author.id, track=track)
+        track, pos_global, pos_local = player.add(requester=ctx.author, track=track)
 
         if player.current is not None and not silent:
             if player.current.stream:
@@ -137,7 +138,7 @@ class Music(commands.Cog):
     async def _play(self, ctx, *, query: str):
         """ Searches and plays a song from a given query. """
         self.logger.debug("Query: %s" % query)
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         query = query.strip('<>')
 
         if not url_rx.match(query):
@@ -175,13 +176,13 @@ class Music(commands.Cog):
     @require_playing(require_user_listening=True)
     async def _seek(self, ctx, *, time: str):
         """ Seeks to a given position in a track. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         if seconds := time_rx.search(time):
             # Convert to milliseconds, include sign
             milliseconds = int(seconds.group())*1000 * (-1 if time.startswith('-1') else 1)
 
             track_time = player.position + milliseconds
-            await player.seek(track_time)
+            await player.seek(int(track_time))
             msg = ctx.localizer.format_str("{seek.track_moved}", _position=timeformatter.format_ms(track_time))
             await ctx.send(msg)
         else:
@@ -193,7 +194,7 @@ class Music(commands.Cog):
     @voteable(requester_override=True, react_to_vote=True)
     async def _skip(self, ctx):
         """ Skips the current track. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         await player.skip()
         embed = self.get_current_song_embed(ctx)
@@ -204,7 +205,7 @@ class Music(commands.Cog):
     @require_playing(require_user_listening=True)
     async def _skip_to(self, ctx, pos: int = 1):
         """ Plays the queue from a specific point. Disregards tracks before the pos. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         # TODO: Do all queue out of range messages the same way
         if pos < 1:
@@ -214,8 +215,11 @@ class Music(commands.Cog):
 
         await player.skip(pos - 1)
 
-        msg = ctx.localizer.format_str("{skip_to.skipped_to}", _title=player.current.title, _pos=pos)
-        await ctx.send(msg)
+        if player.current:
+            msg = ctx.localizer.format_str("{skip_to.skipped_to}", _title=player.current.title, _pos=pos)
+            await ctx.send(msg)
+        else:
+            self.logger.error("Expected current track to be valid due to bounds checks")
 
     @commands.command(name='stop')
     @require_voice_connection()
@@ -223,7 +227,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _stop(self, ctx):
         """ Stops the player and clears its queue. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         player.queue.clear()
         await player.stop()
 
@@ -239,9 +243,9 @@ class Music(commands.Cog):
 
     @commands.command(name='queue')
     @require_queue(require_member_queue=True)
-    async def _queue(self, ctx, *, member: discord.Member = None):
+    async def _queue(self, ctx, *, member: Optional[discord.Member] = None):
         """ Shows the player's queue. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         pagified_queue = QueuePaginator(ctx.localizer, player, color=ctx.me.color, member=member)
         scroller = Scroller(ctx, pagified_queue)
         await scroller.start_scrolling(ClearOn.ManualExit | ClearOn.Timeout)
@@ -258,7 +262,7 @@ class Music(commands.Cog):
     @require_playing()
     async def _pause(self, ctx):
         """ Pauses/Resumes the current track. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         await player.set_pause(not player.paused)
         if player.paused:
             await ctx.send(ctx.localizer.format_str("{resume.paused}"))
@@ -270,8 +274,8 @@ class Music(commands.Cog):
     @require_queue(require_author_queue=True)
     async def _shuffle(self, ctx):
         """ Shuffles your queue. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
-        player.shuffle_user_queue(ctx.author.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player.shuffle_user_queue(ctx.author)
         await ctx.send(ctx.localizer.format_str("{shuffle}"))
 
     @commands.command(name='move')
@@ -304,7 +308,7 @@ class Music(commands.Cog):
         page = 0
         while True:
             # Prompt the user for which track to move
-            selector = move_selector(ctx, player.user_queue(ctx.author.id), "{moved.choose_pos}", True)
+            selector = move_selector(ctx, player.user_queue(ctx.author), "{moved.choose_pos}", True)
             message, track_to_move = await selector.start_scrolling(ClearOn.Timeout, message, page)
             page = selector.page_number
 
@@ -312,7 +316,7 @@ class Music(commands.Cog):
                 break
 
             # Prompt the user for where to move it
-            selector = move_selector(ctx, player.user_queue(ctx.author.id), "{moved.choose_song}", False)
+            selector = move_selector(ctx, player.user_queue(ctx.author), "{moved.choose_song}", False)
             message, track_to_replace = await selector.start_scrolling(ClearOn.Timeout, message, page)
             page = selector.page_number
 
@@ -323,11 +327,11 @@ class Music(commands.Cog):
             # one in the queue. Find the index of both songs in the current queue
 
             # Keep updating the user queue in case it changes while the user is selecting songs
-            user_queue = player.user_queue(ctx.author.id)
+            user_queue = player.user_queue(ctx.author)
             try:
                 pos_initial = user_queue.index(track_to_move[0])
                 pos_final = user_queue.index(track_to_replace[0])
-                player.move_user_track(ctx.author.id, pos_initial, pos_final)
+                player.move_user_track(ctx.author, pos_initial, pos_final)
             except ValueError:
                 # Track not found in queue. Queue could have changed during selection
                 # if a song was skipped or the current song finished
@@ -342,7 +346,7 @@ class Music(commands.Cog):
     async def _remove(self, ctx):
         player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
-        user_queue: List[AudioTrack] = player.user_queue(ctx.author.id)
+        user_queue: List[AudioTrack] = player.user_queue(ctx.author)
 
         tracks_to_remove = []
 
@@ -379,13 +383,13 @@ class Music(commands.Cog):
             paginator = TextPaginator(color=ctx.me.color, title="Removed")
 
             # If the user spent a long time selecting songs the queue might have changed
-            user_queue = player.user_queue(ctx.author.id)
+            user_queue = player.user_queue(ctx.author)
             track_indexes_to_remove = [i for i, track in enumerate(user_queue) if track in tracks_to_remove]
 
             # Sort in reverse order since songs shift index when deleting
             tracks_removed = []
             for track in sorted(track_indexes_to_remove, reverse=True):
-                if removed_track := player.remove_user_track(ctx.author.id, track):
+                if removed_track := player.remove_user_track(ctx.author, track):
                     tracks_removed.append(f"{removed_track.title}")
 
             # We want to display the removed tracks in the original queue order, so reverse the list once again
@@ -400,22 +404,26 @@ class Music(commands.Cog):
     @checks.dj_or()
     @require_voice_connection()
     @require_queue()
-    async def _djremove(self, ctx, pos: int, member: discord.Member = None):
+    async def _djremove(self, ctx, pos: int, member: Optional[discord.Member] = None):
         """ Remove a song from either the global queue or a users queue"""
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         # TODO: add way to allow "member" as regular arg in require_queue() instead of only kwargs
-        queue = player.user_queue(member.id) if member else player.queue
+        queue = player.user_queue(member) if member else player.queue
 
         # TODO: Do all queue out of range messages the same way
         if pos <= len(queue) and pos >= 1:
             if member is None:
                 removed = player.remove_global_track(pos - 1)
             else:
-                removed = player.remove_user_track(member.id, pos - 1)
+                removed = player.remove_user_track(member, pos - 1)
 
-            requester = self.bot.get_user(removed.requester)
-            await ctx.send(ctx.localizer.format_str("{dj_removed}", _title=removed.title, _user=requester.display_name))
+            if removed:
+                requester = self.bot.get_user(removed.requester)
+                await ctx.send(ctx.localizer.format_str("{dj_removed}", _title=removed.title,
+                                                        _user=requester.display_name))
+            else:
+                self.logger.error("Did not remove a track when trying to remove index {pos}, despite bounds check")
         else:
             await ctx.send(ctx.localizer.format_str("{out_of_range}", _len=len(queue)))
 
@@ -425,8 +433,8 @@ class Music(commands.Cog):
     @require_queue(require_member_queue=True)
     async def _user_queue_remove(self, ctx, *, member: discord.Member):
         """ Remove a song from either the global queue or a users queue"""
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
-        player.remove_user_queue(member.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player.remove_user_queue(member)
 
         embed = discord.Embed(description="{dj_remove_user}", color=ctx.me.color)
         embed = ctx.localizer.format_embed(embed, _id=member.id)
@@ -436,8 +444,9 @@ class Music(commands.Cog):
     @commands.command(name='search')
     @require_voice_connection(should_connect=True)
     async def _search(self, ctx, *, query):
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
+        self.logger.debug("Query: %s" % query)
         if not query.startswith('ytsearch:') and not query.startswith('scsearch:'):
             query = 'ytsearch:' + query
 
@@ -478,7 +487,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _disconnect(self, ctx):
         """ Disconnects the player from the voice channel and clears its queue. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         player.queue.clear()
         await player.stop()
@@ -492,7 +501,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _reconnect(self, ctx):
         """ Tries to disconnect then reconnect the player in case the bot gets stuck on a song """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         current_channel = player.channel_id
 
         async def recon():
@@ -508,16 +517,16 @@ class Music(commands.Cog):
             start_time = player.position
             await recon()
             if track:
-                await player.play(track, start_time=start_time)
+                await player.play(track, start_time=int(start_time))
         else:
             await recon()
 
     @commands.command(name='volume')
     @checks.dj_or(alone=True, track_requester=True)
     @require_playing(require_user_listening=True)
-    async def _volume(self, ctx, volume: int = None):
+    async def _volume(self, ctx, volume: Optional[int] = None):
         """ Changes the player's volume. Must be between 0 and 1000. Error Handling for that is done by Lavalink. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         if not volume:
             return await ctx.send(f'🔈 | {player.volume}%')
@@ -538,7 +547,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _forceplay(self, ctx, *, query: str):
         """ Searches and plays a song from a given query. """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         query = query.strip('<>')
 
         if not url_rx.match(query):
@@ -575,11 +584,12 @@ class Music(commands.Cog):
     async def _forcedisconnect(self, ctx):
         """ Attempts to force disconnect the bot without checking if it is connected initially. """
         try:
-            player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+            player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
             player.queue.clear()
             await player.stop()
-        except Exception:
-            self.logger.exception("Error forcedisconnecting")
+        except Exception as e:
+            self.logger.error("Error forcedisconnecting")
+            self.logger.exception(e)
         await ctx.voice_client.disconnect(force=True)
         embed = discord.Embed(description='{disconnect.disconnected}', color=ctx.me.color)
         embed = ctx.localizer.format_embed(embed)
@@ -603,7 +613,7 @@ class Music(commands.Cog):
     @checks.dj_or(alone=True)
     async def _boost(self, ctx, boost: bool = False):
         """ Set the equalizer to bass boost the music """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         if boost is not None:
             await player.bassboost(boost)
@@ -630,7 +640,7 @@ class Music(commands.Cog):
     @commands.command(name='history')
     async def _history(self, ctx):
         """ Show the last 10 songs played """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         history = player.get_history()
         if not history:
             embed = discord.Embed(description='{history.empty}', color=ctx.me.color)
@@ -647,8 +657,9 @@ class Music(commands.Cog):
         embed = discord.Embed(title=ctx.localizer.format_str('{history.title}'), color=ctx.me.color,
                               description=description)
 
-        if thumbnail_url := player.current.extra["thumbnail_url"]:
-            embed.set_thumbnail(url=thumbnail_url)
+        if current := player.current:
+            if thumbnail_url := current.extra["thumbnail_url"]:
+                embed.set_thumbnail(url=thumbnail_url)
         await ctx.send(embed=embed)
 
     @commands.cooldown(1, 5, commands.BucketType.guild)
@@ -656,7 +667,7 @@ class Music(commands.Cog):
     async def _lyrics(self, ctx, *query: str):
 
         # TODO:
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
 
         genius_access_token = self.bot.APIkeys.get('genius', None)
 
@@ -666,13 +677,13 @@ class Music(commands.Cog):
         excluded_words = ['music', 'video', 'version', 'original', 'lyrics', 'lyric',
                           'official', 'live', 'instrumental', 'audio', 'hd']
 
-        query = ' '.join(query)
+        query_as_string = ' '.join(query)
 
-        if not query and player.is_playing:
-            query = player.current.title
-            query = re.sub(r'[-()_\[\]]', '', query)
-            filtered_words = [word for word in query.split() if word.lower() not in excluded_words]
-            query = ' '.join(filtered_words)
+        if not query_as_string and player.is_playing and player.current:
+            query_as_string = player.current.title
+            query_as_string = re.sub(r'[-()_\[\]]', '', query_as_string)
+            filtered_words = [word for word in query_as_string.split() if word.lower() not in excluded_words]
+            query_as_string = ' '.join(filtered_words)
 
         async def get_site_content(url):
             async with self.bot.session.get(url) as resp:
@@ -683,8 +694,8 @@ class Music(commands.Cog):
         status_msg = await ctx.send(embed=embed)
 
         try:
-            url = 'https://api.genius.com/search?' + urllib.parse.urlencode(
-                {'access_token': genius_access_token, 'q': query})
+            url = 'https://api.genius.com/search?' + urlparse.urlencode(
+                {'access_token': genius_access_token, 'q': query_as_string})
             result = await get_site_content(url)
             response = json.loads(result)
             song_id = response['response']['hits'][0]['result']['id']
@@ -715,7 +726,7 @@ class Music(commands.Cog):
                 await ctx.send(embed=page)
         else:
             paginator.add_page_indicator(ctx.localizer)
-            await Scroller(ctx, paginator).start_scrolling(ClearOn.AnyExi)
+            await Scroller(ctx, paginator).start_scrolling(ClearOn.AnyExit)
 
     @commands.command(name='scrub')
     @checks.dj_or(alone=True)
@@ -755,7 +766,7 @@ class Music(commands.Cog):
     async def _loop(self, ctx):
         # This is done using subcommands to have separate vote counts for starting and stopping.
         if ctx.invoked_subcommand is None:
-            player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+            player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
             embed = discord.Embed(color=ctx.me.color, title='Loop status')
 
             if player.looping:
@@ -769,7 +780,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _loop_start(self, ctx):
         """ Set the equalizer to bass boost the music """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         player.enable_looping(True)
         embed = discord.Embed(color=ctx.me.color)
         embed.description = 'Looping turned on'
@@ -781,7 +792,7 @@ class Music(commands.Cog):
     @voteable(DJ_override=True, react_to_vote=True)
     async def _loop_stop(self, ctx):
         """ Set the equalizer to bass boost the music """
-        player = self.bot.lavalink.player_manager.get(ctx.guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(ctx.guild.id)
         player.enable_looping(False)
         embed = discord.Embed(color=ctx.me.color)
         embed.description = 'Looping turned off'
@@ -794,7 +805,7 @@ class Music(commands.Cog):
     async def track_hook(self, event):
         if isinstance(event, TrackEndEvent):
             channel = self.bot.get_channel(event.player.fetch('channel'))
-            player = self.bot.lavalink.player_manager.get(channel.guild.id)
+            player: MixPlayer = self.bot.lavalink.player_manager.get(channel.guild.id)
             player.skip_voters.clear()
 
         if isinstance(event, TrackStartEvent):
@@ -814,30 +825,31 @@ class Music(commands.Cog):
             pass
 
     @commands.Cog.listener()
-    async def on_voice_state_update(self, member, before, after):
+    async def on_voice_state_update(self, member: discord.Member, _: discord.VoiceState, after: discord.VoiceState):
         """ Updates listeners when the bot or a user changes voice state """
         if member.id == self.bot.user.id and after.channel is not None:
             voice_channel = after.channel
-            player = self.bot.lavalink.player_manager.get(member.guild.id)
+            player: MixPlayer = self.bot.lavalink.player_manager.get(member.guild.id)
             player.clear_listeners()
             for member in voice_channel.members:
                 if not member.bot:
                     player.update_listeners(member, member.voice)
 
         if not member.bot:
-            player = self.bot.lavalink.player_manager.get(member.guild.id)
+            player: MixPlayer = self.bot.lavalink.player_manager.get(member.guild.id)
             if player is not None:
                 player.update_listeners(member, after)
                 await self.check_leave_voice(member.guild)
 
-    async def check_leave_voice(self, guild):
+    async def check_leave_voice(self, guild: discord.Guild):
         """ Checks if the bot should leave the voice channel """
         # TODO, disconnect timer?
-        player = self.bot.lavalink.player_manager.get(guild.id)
+        player: MixPlayer = self.bot.lavalink.player_manager.get(guild.id)
         if len(player.listeners) == 0 and player.is_connected:
             if player.queue.empty and player.current is None:
                 await player.stop()
-                await guild.voice_client.disconnect()
+                if voice_client := guild.voice_client:
+                    await voice_client.disconnect(force=False)
 
     async def leave_check(self):
         for player_id in self.bot.lavalink.player_manager.players:
@@ -848,10 +860,14 @@ class Music(commands.Cog):
         try:
             await self.leave_check()
         except Exception as err:
-            self.logger.debug("Error in leave_timer loop.\nTraceback: %s" % (err))
+            self.logger.error("Error in leave_timer loop")
+            self.logger.exception(err)
 
 
 def wrap_in_button_callback(func, *args):
+    """
+    Take a callback and convert it to the form required by a SelectorItem
+    """
     async def inner(_interaction, _button):
         return await func(*args)
     return inner
diff --git a/musicbot/cogs/music/decorators.py b/musicbot/cogs/music/decorators.py
index b9d69ce..4612d3e 100644
--- a/musicbot/cogs/music/decorators.py
+++ b/musicbot/cogs/music/decorators.py
@@ -136,7 +136,7 @@ def require_queue(require_member_queue=False, require_author_queue=False):
             if require_member_queue:
                 try:
                     if member := kwargs['member']:  # Ignore if member is None
-                        user_queue = player.user_queue(member.id)
+                        user_queue = player.user_queue(member)
                         if not user_queue:
                             embed = discord.Embed(description='{queue.user_empty}', color=ctx.me.color)
                             embed = ctx.localizer.format_embed(embed, _user=member.display_name)
@@ -145,7 +145,7 @@ def require_queue(require_member_queue=False, require_author_queue=False):
                     raise Exception("require_member_error can only be used on commands with a member keyword argument")
 
             if require_author_queue:
-                user_queue = player.user_queue(ctx.author.id)
+                user_queue = player.user_queue(ctx.author)
                 if not user_queue:
                     embed = discord.Embed(description='{my_queue}', color=ctx.me.color)
                     embed = ctx.localizer.format_embed(embed)
diff --git a/musicbot/cogs/nodemanager.py b/musicbot/cogs/nodemanager.py
index 5e4c501..c0699ff 100644
--- a/musicbot/cogs/nodemanager.py
+++ b/musicbot/cogs/nodemanager.py
@@ -47,16 +47,18 @@ class NodeManager(commands.Cog):
             for node in self.bot.lavalink.node_manager.nodes:
                 name_cache.append(node.name)
 
+            self.logger.debug("BEFORE")
             for node in conf['lavalink nodes'] + self.settings.get('lavalink', 'nodes', []):
                 if node['name'] in name_cache:
                     continue
-                name_cache.append(node['name'])
 
                 self.bot.lavalink.add_node(**node)
+
                 self.logger.debug("Adding Lavalink node: %s on %s with the port %s in %s" % (
                     node['name'], node['host'],
                     node['port'], node['region'],))
                 new_nodes.append({**node})
+                name_cache.append(node['name'])
             return new_nodes
 
     async def _regioner(self, region):
@@ -163,7 +165,7 @@ class NodeManager(commands.Cog):
                 embed.title = 'Removed node from bot'
                 await ctx.send(embed=embed)
                 self.bot.lavalink.node_manager.remove_node(_node)
-                self.logger.info("Removed Lavalink node: %s" % _node.host)
+                self.logger.info("Removed Lavalink node: %s, %s" % (_node.name, _node.host))
 
         self.settings.set('lavalink', 'nodes', [self.get_node_properties(n) for
                                                 n in self.bot.lavalink.node_manager.nodes])
diff --git a/musicbot/utils/mixplayer/mixqueue.py b/musicbot/utils/mixplayer/mixqueue.py
index 53eebbc..f63a2bd 100644
--- a/musicbot/utils/mixplayer/mixqueue.py
+++ b/musicbot/utils/mixplayer/mixqueue.py
@@ -1,3 +1,6 @@
+# Discord Packages
+from lavalink.models import AudioTrack
+
 import logging
 from collections import OrderedDict, deque
 from itertools import chain, cycle, islice
@@ -5,7 +8,7 @@ from random import shuffle
 from typing import Generic, Iterable, Iterator, List, Optional, Tuple, TypeVar
 
 # Would like to ensure the T has a "requester" attribute, but don't know if that is possible
-T = TypeVar('T')
+T = TypeVar('T', bound=AudioTrack)
 QueueType = List[T]
 
 
@@ -31,7 +34,6 @@ class MixQueue(Generic[T]):
         self.looping = False
         self.loop_offset = 0
         self.logger = logging.getLogger("musicbot").getChild("Queue")
-        self.logger = self.logger.getChild("Queue")
 
     def __str__(self) -> str:
         tmp = ''
@@ -96,9 +98,9 @@ class MixQueue(Generic[T]):
                     self._history.append(next_track)
                     return next_track
                 except IndexError as e:
-                    self.logger.error(e)
-                    self.logger.error(self.loop_offset)
-                    self.logger.error(len(self))
+                    self.logger.error(f"Failed to get the next track in looping mode: loop offset {self.loop_offset}." +
+                                      " Queue length: {len(self)}")
+                    self.logger.exception(e)
                     self.loop_offset = min(self.loop_offset, len(self)-1)
             else:
                 if first_queue := self.first_queue:
@@ -123,12 +125,13 @@ class MixQueue(Generic[T]):
             localpos = pos
 
         # Return info about track position
-        return track, self._loc_to_glob(requester, localpos), localpos
+        global_position = self._loc_to_glob(requester, localpos)
+        return track, global_position, localpos
 
-    def add_next_track(self, track: T) -> None:
+    def add_priorty_queue_track(self, track: T) -> None:
         self.priority_queue.append(track)
 
-    def remove_user_queue(self, requester: int) -> None:
+    def remove_user_queue(self, requester: int) -> QueueType:
         user_queue = self.queues.get(requester, [])
         if user_queue:
             if self.looping:
@@ -137,6 +140,7 @@ class MixQueue(Generic[T]):
                     self.remove_user_track(requester, pos)
             else:
                 self.queues.pop(requester)
+        return user_queue
 
     def remove_user_track(self, requester: int, pos: int) -> Optional[T]:
         user_queue = self.queues.get(requester)
@@ -172,6 +176,7 @@ class MixQueue(Generic[T]):
                 queue.insert(final, track)
                 return track
             except IndexError:
+                self.logger.debug(f"Got invalid index when moving track from {initial} to {final}")
                 pass
 
     def shuffle_user_queue(self, requester: int) -> None:
@@ -180,17 +185,19 @@ class MixQueue(Generic[T]):
             shuffle(queue)
 
     def enable_looping(self, looping: bool) -> None:
-        if (not self.looping) and looping:  # Not enabled and turning on
+        if (not self.looping) and looping:  # Enable only if not already enabled
             self.looping = looping
             self.loop_offset = 0
-        elif self.looping and not looping:  # Enabled to turning off
-            tmp = [track for track in self.get_queue()]
-            for key, _ in self.queues.items():
-                self.queues = OrderedDict()
+            self.logger.debug("Looping enabled")
+        elif self.looping and not looping:  # Disable only if enabled
+            # Copy queue in current (looping) state
+            queue_copy = [track for track in self.get_queue()]
+            self.queues = OrderedDict()
             self.looping = looping
-            for track in tmp:
+            for track in queue_copy:
                 self.add_track(track.requester, track)
             self.loop_offset = 0
+            self.logger.debug("Looping disabled, queue reordered")
 
     # Switches the order of user queues
     def _shift_queues(self) -> None:
@@ -217,9 +224,9 @@ class MixQueue(Generic[T]):
                     globpos += 1
         return globpos
 
-    def _glob_to_loc(self, pos: int) -> Tuple[Optional[T], Optional[int]]:
+    def _glob_to_loc(self, pos: int) -> Tuple[Optional[int], Optional[int]]:
         try:
-            song = next(islice(self, pos, pos + 1))
+            song: T = next(islice(self, pos, pos + 1))
         except (ValueError, StopIteration):
             return None, None
         user_queue = self.queues.get(song.requester, [])
diff --git a/musicbot/utils/mixplayer/player.py b/musicbot/utils/mixplayer/player.py
index 9b7046d..c43d7f5 100644
--- a/musicbot/utils/mixplayer/player.py
+++ b/musicbot/utils/mixplayer/player.py
@@ -5,10 +5,13 @@ from lavalink import AudioTrack, DefaultPlayer, Node
 from lavalink.events import QueueEndEvent, TrackEndEvent, TrackExceptionEvent, TrackStartEvent, TrackStuckEvent
 from lavalink.filters import Equalizer, Timescale
 
+import logging
 from typing import Dict, List, Optional, Set, Tuple
 
 from .mixqueue import MixQueue
 
+RequesterType = discord.Member
+
 
 class MixPlayer(DefaultPlayer):
     def __init__(self, guild_id: int, node: Node):
@@ -16,11 +19,12 @@ class MixPlayer(DefaultPlayer):
 
         self.queue: MixQueue[AudioTrack] = MixQueue()
 
-        self.listeners: Set[int] = set()
-        self.voteables: Dict[int, Set[int]] = {}
+        self.listeners: Set[RequesterType] = set()
+        self.voteables: Dict[int, Set[RequesterType]] = {}
         self.skip_voters: Set[int] = set()
         self.boosted: bool = False
         self.nightcore_enabled: bool = False
+        self.logger = logging.getLogger("musicbot").getChild("MixPlayer")
         bands = [
             (0, 0.15),
             (1, 0.15),
@@ -36,38 +40,50 @@ class MixPlayer(DefaultPlayer):
         self.nightcore_filter: lavalink.Filter = Timescale()
         self.nightcore_filter.update(speed=1.25, pitch=1.25)
 
-    def add(self, requester: int, track: AudioTrack, pos: Optional[int] = None) -> Tuple[AudioTrack, int, int]:
+    def add(self, requester: RequesterType, track: AudioTrack,
+            pos: Optional[int] = None) -> Tuple[AudioTrack, int, int]:
         """ Adds a track to the queue. """
-        return self.queue.add_track(requester, track, pos)
+        track, global_position, localpos = self.queue.add_track(requester.id, track, pos)
+        self.logger.info(f"Track {track.title} added for {requester.display_name} @ ({global_position}, {localpos}).")
+        return track, global_position, localpos
 
     def add_priority(self, track: AudioTrack):
         """ Adds a track to beginning of the queue """
-        self.queue.add_next_track(track)
+        self.queue.add_priorty_queue_track(track)
+        self.logger.info(f"Track {track} added to priority queue.")
 
-    def move_user_track(self, requester: int, initial: int, final: int):
+    def move_user_track(self, requester: RequesterType, initial: int, final: int):
         """ Moves a track in a users queue"""
-        return self.queue.move_user_track(requester, initial, final)
+        if moved := self.queue.move_user_track(requester.id, initial, final):
+            self.logger.info(f"Track {moved.title} moved from {initial} to {final}" +
+                             f"for in queue for {requester.display_name}")
 
-    def remove_user_queue(self, requester: int):
-        self.queue.remove_user_queue(requester)
+    def remove_user_queue(self, requester: RequesterType):
+        removed = self.queue.remove_user_queue(requester.id)
+        if removed:  # Removed queues can be empty
+            self.logger.info(f"Queue for requester {requester.display_name} removed. {len(removed)} tracks removed")
+        else:
+            self.logger.debug(f"User {requester.display_name} has no more tracks. Remove from queue")
 
-    def remove_user_track(self, requester: int, pos: int) -> Optional[AudioTrack]:
+    def remove_user_track(self, requester: RequesterType, pos: int) -> Optional[AudioTrack]:
         """ Removes the song at <pos> from the queue of requester """
-        return self.queue.remove_user_track(requester, pos)
+        if track := self.queue.remove_user_track(requester.id, pos):
+            self.logger.info(f"Track {track.title} for requester {requester.display_name} removed.")
+            return track
 
     def remove_global_track(self, pos: int) -> Optional[AudioTrack]:
         """ Removes the song at <pos> in the global queue """
         return self.queue.remove_global_track(pos)
 
-    def shuffle_user_queue(self, requester: int):
+    def shuffle_user_queue(self, requester: RequesterType):
         """ Randomly reorders the queue of requester """
-        self.queue.shuffle_user_queue(requester)
+        self.queue.shuffle_user_queue(requester.id)
 
-    def user_queue(self, user: int) -> List[AudioTrack]:
-        return self.queue.get_user_queue(user)
+    def user_queue(self, requester: RequesterType) -> List[AudioTrack]:
+        return self.queue.get_user_queue(requester.id)
 
-    def user_queue_with_global_index(self, user: int) -> List[Tuple[AudioTrack, int]]:
-        return self.queue.get_user_queue_with_index(user)
+    def user_queue_with_global_index(self, requester: RequesterType) -> List[Tuple[AudioTrack, int]]:
+        return self.queue.get_user_queue_with_index(requester.id)
 
     def global_queue(self) -> List[AudioTrack]:
         return self.queue.get_queue()
@@ -76,9 +92,9 @@ class MixPlayer(DefaultPlayer):
         return self.queue.history
 
     def queue_duration(self, include_current: bool = False,
-                       member: Optional[discord.Member] = None, end_pos: Optional[int] = None):
+                       member: Optional[RequesterType] = None, end_pos: Optional[int] = None):
         duration = 0
-        queue = self.user_queue(member.id) if member else self.queue
+        queue = self.user_queue(member) if member else self.queue
 
         for i, track in enumerate(queue):
             if i == end_pos:
@@ -101,8 +117,9 @@ class MixPlayer(DefaultPlayer):
 
         if not track:
             if self.queue.empty:
-                self.boosted = False
-                self.nightcore_enabled = False
+                self.logger.debug("No track provided to play function and queue is empty. Resetting Audio filters")
+                await self.bassboost(False)
+                await self.nightcoreify(False)
                 await self.stop()
                 await self.node._dispatch_event(QueueEndEvent(self))
                 return
@@ -117,11 +134,14 @@ class MixPlayer(DefaultPlayer):
         await self.node._send(op='play', guildId=str(self.guild_id),
                               track=track.track, startTime=start_time)
         await self.node._dispatch_event(TrackStartEvent(self, track))
+        self.logger.info(f"Playing track: {track.title}")
 
     async def skip(self, pos: int = 0):
         """ Plays the next track in the queue, if any. """
-        for i in range(pos):
-            _ = self.queue.pop_first()
+        for _ in range(pos):
+            track = self.queue.pop_first()
+            self.logger.debug(f"Track {track} skipped")
+        self.logger.info(f"Skipped {pos + 1} tracks")
         self.clear_votes()
         await self.play()
 
@@ -129,36 +149,43 @@ class MixPlayer(DefaultPlayer):
         """ Stops the player. """
         await self.node._send(op='stop', guildId=str(self.guild_id))
         self.current = None
-        self.queue.looping = False
+        self.queue.enable_looping(False)
+        self.logger.info("Music player stopped, clearing current track and stopping looping")
         self.clear_votes()
 
-    def update_listeners(self, member, voice_state):
+    def update_listeners(self, member: RequesterType, voice_state):
         if self.channel_id is not None:
             vc = int(self.channel_id)
             if voice_state.channel is None or voice_state.channel.id != vc:
+                self.logger.debug(f"User {member.display_name} left the voice channel")
                 self.listeners.discard(member)
                 self.remove_member_votes(member)
             else:
                 if voice_state.deaf or voice_state.self_deaf:
+                    self.logger.debug(f"User {member.display_name} is now deafened")
                     self.listeners.discard(member)
                     self.remove_member_votes(member)
                 else:
                     self.listeners.add(member)
+            self.logger.debug(f"Member voice state update. Votes are now {self.voteables}")
 
     def clear_listeners(self):
+        self.logger.debug("Listeners cleared")
         self.listeners.clear()
 
-    def add_vote(self, category, member):
+    def add_vote(self, category, member: RequesterType):
         if member in self.listeners:
             if category not in self.voteables:
                 self.voteables[category] = set()
             self.voteables[category].add(member)
+            self.logger.debug(f"{member.display_name} added vote for {category}")
 
-    def remove_member_votes(self, member):
+    def remove_member_votes(self, member: RequesterType):
         for _, votes in self.voteables.items():
             votes.discard(member)
+        self.logger.debug(f"Removing votes for {member.display_name}.")
 
-    def get_voters(self, category):
+    def get_voters(self, category) -> Set[RequesterType]:
         if category not in self.voteables:
             self.voteables[category] = set()
         return self.voteables[category]
@@ -167,7 +194,7 @@ class MixPlayer(DefaultPlayer):
         for _, votes in self.voteables.items():
             votes.clear()
 
-    def enable_looping(self, looping):
+    def enable_looping(self, looping: bool):
         if (not self.queue.looping) and looping:
             self.queue.enable_looping(looping)
             if track := self.current:
@@ -180,6 +207,7 @@ class MixPlayer(DefaultPlayer):
         """ Handles the given event as necessary. """
         if isinstance(event, (TrackStuckEvent, TrackExceptionEvent)) or \
                 isinstance(event, TrackEndEvent) and event.reason == 'FINISHED':
+            self.logger.debug("Track ended, clearing votes")
             self.skip_voters.clear()
             for _, votes in self.voteables.items():
                 votes.clear()
@@ -190,13 +218,16 @@ class MixPlayer(DefaultPlayer):
         if boost:
             await self.set_filter(self.bass_boost_filter)
         else:
+            self.logger.info("Disabling bass boost")
             await self.remove_filter(self.bass_boost_filter)
 
     async def nightcoreify(self, nightcore: bool = False):
         self.nightcore_enabled = nightcore
         if nightcore:
+            self.logger.info("Enabling nightcore mode")
             await self.set_filter(self.nightcore_filter)
         else:
+            self.logger.info("Disabling nightcore mode")
             await self.remove_filter(self.nightcore_filter)
 
     @property
diff --git a/musicbot/utils/mixplayer/test_queue.py b/musicbot/utils/mixplayer/test_queue.py
index f515e31..5f73766 100644
--- a/musicbot/utils/mixplayer/test_queue.py
+++ b/musicbot/utils/mixplayer/test_queue.py
@@ -62,8 +62,8 @@ class TestMixQueue():
     def test_priority_queue(self):
         queue = self.setup_baisc_queue()
 
-        queue.add_next_track("priority_item1")
-        queue.add_next_track("priority_item2")
+        queue.add_priorty_queue_track("priority_item1")
+        queue.add_priorty_queue_track("priority_item2")
 
         assert queue.pop_first() == "priority_item1"
         assert queue.pop_first() == "priority_item2"
diff --git a/musicbot/utils/userinteraction/paginators/queuepaginator.py b/musicbot/utils/userinteraction/paginators/queuepaginator.py
index f946106..02d2fd3 100644
--- a/musicbot/utils/userinteraction/paginators/queuepaginator.py
+++ b/musicbot/utils/userinteraction/paginators/queuepaginator.py
@@ -16,7 +16,7 @@ class QueuePaginator(TextPaginator):
         duration = player.queue_duration(member=member, include_current=include_current)
 
         if member:
-            member_queue = player.user_queue_with_global_index(member.id)
+            member_queue = player.user_queue_with_global_index(member)
             title = localizer.format_str("{queue.userqueue}",
                                          _user=member.display_name, _length=len(member_queue), _duration=duration)