add logging and fix other things

pomice/enums.py

@@ -174,7 +174,7 @@ class RouteIPType(Enum):
 
 class URLRegex:
     """
-    The enums for all the URL Regexes in use by Pomice.
+    The enum for all the URL Regexes in use by Pomice.
 
     URLRegex.SPOTIFY_URL returns the Spotify URL Regex.
 
@@ -245,3 +245,33 @@ class URLRegex:
     LAVALINK_SEARCH = re.compile(r"(?P<type>ytm?|sc)search:")
 
     BASE_URL = re.compile(r"https?://(?:www\.)?.+")
+
+
+class LogLevel(Enum):
+    """
+    The enum for specifying the logging level within Pomice.
+    This class serves as shorthand for logging.<level>
+    This enum is exclusively for the logging feature in Pomice.
+    If you are not using this feature, this class is not necessary.
+
+
+    LogLevel.DEBUG sets the logging level to "debug".
+
+    LogLevel.INFO sets the logging level to "info".
+
+    LogLevel.WARN sets the logging level to "warn".
+
+    LogLevel.ERROR sets the logging level to "error".
+
+    LogLevel.CRITICAL sets the logging level to "CRITICAL".
+
+    """
+
+    DEBUG = 10
+    INFO = 20
+    WARN = 30
+    ERROR = 40
+    CRITICAL = 50
+
+    def __str__(self) -> str:
+        return self.value

pomice/player.py

@@ -30,6 +30,7 @@ from .objects import Playlist
 from .objects import Track
 from .pool import Node
 from .pool import NodePool
+from pomice.utils import LavalinkVersion
 
 if TYPE_CHECKING:
     from discord.types.voice import VoiceServerUpdate
@@ -158,6 +159,7 @@ class Player(VoiceProtocol):
         self._last_position: int = 0
         self._last_update: float = 0
         self._ending_track: Optional[Track] = None
+        self._log = self._node._log
 
         self._voice_state: dict = {}
 
@@ -260,20 +262,17 @@ class Player(VoiceProtocol):
         return self.guild.id not in self._node._players
 
     def _adjust_end_time(self):
-        version = self._node._version
+        if self._node._version >= LavalinkVersion(3, 7, 5):
-        if version.major == 4:
             return None
-        if version.major == 3:
+
-            if version.minor == 7 and version.fix == 5:
+        return "0"
-                return None
-            else:
-                return "0"
 
     async def _update_state(self, data: dict) -> None:
         state: dict = data.get("state", {})
         self._last_update = int(state.get("time", 0))
         self._is_connected = bool(state.get("connected"))
         self._last_position = int(state.get("position", 0))
+        self._log.debug(f"Got player update state with data {state}")
 
     async def _dispatch_voice_update(self, voice_data: Optional[Dict[str, Any]] = None) -> None:
         if {"sessionId", "event"} != self._voice_state.keys():
@@ -294,6 +293,8 @@ class Player(VoiceProtocol):
             data={"voice": data},
         )
 
+        self._log.debug(f"Dispatched voice update to {state['event']['endpoint']} with data {data}")
+
     async def on_voice_server_update(self, data: VoiceServerUpdate) -> None:
         self._voice_state.update({"event": data})
         await self._dispatch_voice_update(self._voice_state)
@@ -330,6 +331,8 @@ class Player(VoiceProtocol):
         if isinstance(event, TrackStartEvent):
             self._ending_track = self._current
 
+        self._log.debug(f"Dispatched event {data['type']} to player.")
+
     async def _swap_node(self, *, new_node: Node) -> None:
         if self.current:
             data: dict = {"position": self.position, "encodedTrack": self.current.track_id}
@@ -348,6 +351,8 @@ class Player(VoiceProtocol):
             data=data,
         )
 
+        self._log.debug(f"Swapped all players to new node {new_node._identifier}.")
+
     async def get_tracks(
         self,
         query: str,
@@ -401,6 +406,8 @@ class Player(VoiceProtocol):
             data={"encodedTrack": None},
         )
 
+        self._log.debug(f"Player has been stopped.")
+
     async def disconnect(self, *, force: bool = False) -> None:
         """Disconnects the player from voice."""
         try:
@@ -426,14 +433,13 @@ class Player(VoiceProtocol):
             guild_id=self._guild.id,
         )
 
+        self._log.debug("Player has been destroyed.")
+
     async def play(
         self, track: Track, *, start: int = 0, end: int = 0, ignore_if_playing: bool = False
     ) -> Track:
         """Plays a track. If a Spotify track is passed in, it will be handled accordingly."""
 
-        end_time = self._adjust_end_time()
-        print(f"got end time of {end_time}")
-
         # Make sure we've never searched the track before
         if track.original is None:
             # First lets try using the tracks ISRC, every track has one (hopefully)
@@ -465,7 +471,7 @@ class Player(VoiceProtocol):
             data = {
                 "encodedTrack": search.track_id,
                 "position": str(start),
-                "endTime": end_time,
+                "endTime": self._adjust_end_time(),
             }
             track.original = search
             track.track_id = search.track_id
@@ -474,7 +480,7 @@ class Player(VoiceProtocol):
             data = {
                 "encodedTrack": track.track_id,
                 "position": str(start),
-                "endTime": end_time,
+                "endTime": self._adjust_end_time(),
             }
 
         # Lets set the current track before we play it so any
@@ -515,6 +521,10 @@ class Player(VoiceProtocol):
             query=f"noReplace={ignore_if_playing}",
         )
 
+        self._log.debug(
+            f"Playing {track.title} from uri {track.uri} with a length of {track.length}",
+        )
+
         return self._current
 
     async def seek(self, position: float) -> float:
@@ -533,6 +543,8 @@ class Player(VoiceProtocol):
             guild_id=self._guild.id,
             data={"position": position},
         )
+
+        self._log.debug(f"Seeking to {position}.")
         return self.position
 
     async def set_pause(self, pause: bool) -> bool:
@@ -544,6 +556,8 @@ class Player(VoiceProtocol):
             data={"paused": pause},
         )
         self._paused = pause
+
+        self._log.debug(f"Player has been {'paused' if pause else 'resumed'}.")
         return self._paused
 
     async def set_volume(self, volume: int) -> int:
@@ -555,6 +569,8 @@ class Player(VoiceProtocol):
             data={"volume": volume},
         )
         self._volume = volume
+
+        self._log.debug(f"Player volume has been adjusted to {volume}")
         return self._volume
 
     async def add_filter(self, _filter: Filter, fast_apply: bool = False) -> Filters:
@@ -573,7 +589,10 @@ class Player(VoiceProtocol):
             guild_id=self._guild.id,
             data={"filters": payload},
         )
+
+        self._log.debug(f"Filter has been applied to player with tag {_filter.tag}")
         if fast_apply:
+            self._log.debug(f"Fast apply passed, now applying filter instantly.")
             await self.seek(self.position)
 
         return self._filters
@@ -594,7 +613,9 @@ class Player(VoiceProtocol):
             guild_id=self._guild.id,
             data={"filters": payload},
         )
+        self._log.debug(f"Filter has been removed from player with tag {filter_tag}")
         if fast_apply:
+            self._log.debug(f"Fast apply passed, now removing filter instantly.")
             await self.seek(self.position)
 
         return self._filters
@@ -618,6 +639,8 @@ class Player(VoiceProtocol):
             guild_id=self._guild.id,
             data={"filters": {}},
         )
+        self._log.debug(f"All filters have been removed from player.")
 
         if fast_apply:
+            self._log.debug(f"Fast apply passed, now removing all filters instantly.")
             await self.seek(self.position)

pomice/pool.py

@@ -1,8 +1,10 @@
 from __future__ import annotations
 
 import asyncio
+import logging
 import random
 import re
+import time
 from typing import Any
 from typing import Dict
 from typing import List
@@ -20,6 +22,7 @@ from . import __version__
 from . import applemusic
 from . import spotify
 from .enums import *
+from .enums import LogLevel
 from .exceptions import AppleMusicNotEnabled
 from .exceptions import InvalidSpotifyClientAuthorization
 from .exceptions import LavalinkVersionIncompatible
@@ -102,6 +105,7 @@ class Node:
         spotify_client_secret: Optional[str] = None,
         apple_music: bool = False,
         fallback: bool = False,
+        log_level: LogLevel = LogLevel.INFO,
     ):
         self._bot: commands.Bot = bot
         self._host: str = host
@@ -112,6 +116,7 @@ class Node:
         self._heartbeat: int = heartbeat
         self._secure: bool = secure
         self._fallback: bool = fallback
+        self._log_level: LogLevel = log_level
 
         self._websocket_uri: str = f"{'wss' if self._secure else 'ws'}://{self._host}:{self._port}"
         self._rest_uri: str = f"{'https' if self._secure else 'http'}://{self._host}:{self._port}"
@@ -126,6 +131,7 @@ class Node:
         self._version: LavalinkVersion = None
 
         self._route_planner = RoutePlanner(self)
+        self._log = self._setup_logging(self._log_level)
 
         if not self._bot.user:
             raise NodeCreationError("Bot user is not ready yet.")
@@ -202,6 +208,20 @@ class Node:
         """Alias for `Node.latency`, returns the latency of the node"""
         return self.latency
 
+    def _setup_logging(self, level: LogLevel) -> logging.Logger:
+        logger = logging.getLogger()
+        handler = logging.StreamHandler()
+        dt_fmt = "%Y-%m-%d %H:%M:%S"
+        formatter = logging.Formatter(
+            "[{asctime}] [{levelname:<8}] {name}: {message}",
+            dt_fmt,
+            style="{",
+        )
+        handler.setFormatter(formatter)
+        logger.setLevel(level)
+        logger.addHandler(handler)
+        return logger
+
     async def _handle_version_check(self, version: str):
         if version.endswith("-SNAPSHOT"):
             # we're just gonna assume all snapshot versions correlate with v4
@@ -328,6 +348,7 @@ class Node:
             headers=self._headers,
             json=data or {},
         ) as resp:
+            self._log.debug(f"Making REST request with method {method} to {uri}")
             if resp.status >= 300:
                 resp_data: dict = await resp.json()
                 raise NodeRestException(
@@ -335,11 +356,20 @@ class Node:
                 )
 
             if method == "DELETE" or resp.status == 204:
+                self._log.debug(
+                    f"REST request with method {method} to {uri} completed sucessfully and returned no data.",
+                )
                 return await resp.json(content_type=None)
 
             if resp.content_type == "text/plain":
+                self._log.debug(
+                    f"REST request with method {method} to {uri} completed sucessfully and returned text with body {await resp.text()}",
+                )
                 return await resp.text()
 
+            self._log.debug(
+                f"REST request with method {method} to {uri} completed sucessfully and returned JSON with body {await resp.json()}",
+            )
             return await resp.json()
 
     def get_player(self, guild_id: int) -> Optional[Player]:
@@ -350,6 +380,8 @@ class Node:
         """Initiates a connection with a Lavalink node and adds it to the node pool."""
         await self._bot.wait_until_ready()
 
+        start = time.perf_counter()
+
         if not self._session:
             self._session = aiohttp.ClientSession()
 
@@ -363,16 +395,26 @@ class Node:
 
             await self._handle_version_check(version=version)
 
+            self._log.debug(f"Version check from node successful. Returned version {version}")
+
             self._websocket = await self._session.ws_connect(
                 f"{self._websocket_uri}/v{self._version.major}/websocket",
                 headers=self._headers,
                 heartbeat=self._heartbeat,
             )
 
+            self._log.debug(
+                f"Connected to node websocket using {self._websocket_uri}/v{self._version.major}/websocket",
+            )
+
             if not self._task:
                 self._task = self._loop.create_task(self._listen())
 
             self._available = True
+
+            end = time.perf_counter()
+
+            self._log.info(f"Connected to node {self._identifier}. Took {end - start:.3f}s")
             return self
 
         except (aiohttp.ClientConnectorError, ConnectionRefusedError):
@@ -392,21 +434,34 @@ class Node:
         """Disconnects a connected Lavalink node and removes it from the node pool.
         This also destroys any players connected to the node.
         """
+
+        start = time.perf_counter()
+
         for player in self.players.copy().values():
             await player.destroy()
+            self._log.debug("All players disconnected from node.")
 
         await self._websocket.close()
         await self._session.close()
+        self._log.debug("Websocket and http session closed.")
+
         if self._spotify_client:
             await self._spotify_client.close()
+            self._log.debug("Spotify client session closed.")
 
         if self._apple_music_client:
             await self._apple_music_client.close()
+            self._log.debug("Apple Music client session closed.")
 
         del self._pool._nodes[self._identifier]
         self.available = False
         self._task.cancel()
 
+        end = time.perf_counter()
+        self._log.info(
+            f"Successfully disconnected from node {self._identifier} and closed all sessions. Took {end - start:.3f}s",
+        )
+
     async def build_track(self, identifier: str, ctx: Optional[commands.Context] = None) -> Track:
         """
         Builds a track using a valid track identifier

pomice/utils.py

@@ -231,3 +231,47 @@ class LavalinkVersion(NamedTuple):
     major: int
     minor: int
     fix: int
+
+    def __eq__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        return (
+            (self.major == other.major) and (self.minor == other.minor) and (self.fix == other.fix)
+        )
+
+    def __ne__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        return not (self == other)
+
+    def __lt__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        if self.major > other.major:
+            return False
+        if self.minor > other.minor:
+            return False
+        if self.fix > other.fix:
+            return False
+        return True
+
+    def __gt__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        return not (self < other)
+
+    def __le__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        return (self < other) or (self == other)
+
+    def __ge__(self, other: object) -> bool:
+        if not isinstance(other, LavalinkVersion):
+            return False
+
+        return (self > other) or (self == other)