From 52a45afd7090841a164d204ccc6803dd5b35ab2e Mon Sep 17 00:00:00 2001 From: cloudwithax Date: Sun, 12 Mar 2023 22:30:43 -0400 Subject: [PATCH] add logging and fix other things --- pomice/enums.py | 32 +++++++++++++++++++++++++++- pomice/player.py | 47 ++++++++++++++++++++++++++++++----------- pomice/pool.py | 55 ++++++++++++++++++++++++++++++++++++++++++++++++ pomice/utils.py | 44 ++++++++++++++++++++++++++++++++++++++ 4 files changed, 165 insertions(+), 13 deletions(-) diff --git a/pomice/enums.py b/pomice/enums.py index 6b3a902..65148a8 100644 --- a/pomice/enums.py +++ b/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"(?Pytm?|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. + 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 diff --git a/pomice/player.py b/pomice/player.py index deea116..9b70010 100644 --- a/pomice/player.py +++ b/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 version.major == 4: + if self._node._version >= LavalinkVersion(3, 7, 5): return None - if version.major == 3: - if version.minor == 7 and version.fix == 5: - return None - else: - return "0" + + 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) diff --git a/pomice/pool.py b/pomice/pool.py index e2f7f89..f2ffd66 100644 --- a/pomice/pool.py +++ b/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 diff --git a/pomice/utils.py b/pomice/utils.py index ce7e6a4..f8a3875 100644 --- a/pomice/utils.py +++ b/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)