diff --git a/redbot/cogs/audio/apis/global_db.py b/redbot/cogs/audio/apis/global_db.py index 8880abce6..be609664d 100644 --- a/redbot/cogs/audio/apis/global_db.py +++ b/redbot/cogs/audio/apis/global_db.py @@ -16,7 +16,6 @@ from redbot.core.commands import Cog from redbot.core.i18n import Translator from ..audio_dataclasses import Query -from ..audio_logging import IS_DEBUG, debug_exc_log if TYPE_CHECKING: from .. import Audio @@ -76,18 +75,17 @@ class GlobalCacheWrapper: params={"query": query}, ) as r: search_response = await r.json(loads=json.loads) - if IS_DEBUG and "x-process-time" in r.headers: - log.debug( - "GET || Ping %s || Status code %d || %s", - r.headers.get("x-process-time"), - r.status, - query, - ) + log.trace( + "GET || Ping %s || Status code %d || %s", + r.headers.get("x-process-time"), + r.status, + query, + ) if "tracks" not in search_response: return {} return search_response - except Exception as err: - debug_exc_log(log, err, "Failed to Get query: %s/%s", api_url, query) + except Exception as exc: + log.trace("Failed to Get query: %s/%s", api_url, query, exc_info=exc) return {} async def get_spotify(self, title: str, author: Optional[str]) -> dict: @@ -108,19 +106,18 @@ class GlobalCacheWrapper: params=params, ) as r: search_response = await r.json(loads=json.loads) - if IS_DEBUG and "x-process-time" in r.headers: - log.debug( - "GET/spotify || Ping %s || Status code %d || %s - %s", - r.headers.get("x-process-time"), - r.status, - title, - author, - ) + log.trace( + "GET/spotify || Ping %s || Status code %d || %s - %s", + r.headers.get("x-process-time"), + r.status, + title, + author, + ) if "tracks" not in search_response: return {} return search_response - except Exception as err: - debug_exc_log(log, err, "Failed to Get query: %s", api_url) + except Exception as exc: + log.trace("Failed to Get query: %s", api_url, exc_info=exc) return {} async def post_call(self, llresponse: LoadResult, query: Optional[Query]) -> None: @@ -145,15 +142,14 @@ class GlobalCacheWrapper: params={"query": query}, ) as r: await r.read() - if IS_DEBUG and "x-process-time" in r.headers: - log.debug( - "GET || Ping %s || Status code %d || %s", - r.headers.get("x-process-time"), - r.status, - query, - ) - except Exception as err: - debug_exc_log(log, err, "Failed to post query: %s", query) + log.trace( + "GET || Ping %s || Status code %d || %s", + r.headers.get("x-process-time"), + r.status, + query, + ) + except Exception as exc: + log.trace("Failed to post query: %s", query, exc_info=exc) await asyncio.sleep(0) async def update_global(self, llresponse: LoadResult, query: Optional[Query] = None): diff --git a/redbot/cogs/audio/apis/interface.py b/redbot/cogs/audio/apis/interface.py index 7ec55ecec..1353446d0 100644 --- a/redbot/cogs/audio/apis/interface.py +++ b/redbot/cogs/audio/apis/interface.py @@ -23,7 +23,6 @@ from redbot.core.utils import AsyncIter from redbot.core.utils.dbtools import APSWConnectionWrapper from ..audio_dataclasses import Query -from ..audio_logging import IS_DEBUG, debug_exc_log from ..errors import DatabaseError, SpotifyFetchError, TrackEnqueueError, YouTubeApiError from ..utils import CacheLevel, Notifier from .api_utils import LavalinkCacheFetchForGlobalResult @@ -101,7 +100,7 @@ class AudioAPIInterface: results = LoadResult(track) track = random.choice(list(results.tracks)) except Exception as exc: - debug_exc_log(log, exc, "Failed to fetch a random track from database") + log.trace("Failed to fetch a random track from database", exc_info=exc) track = {} if not track: @@ -148,26 +147,23 @@ class AudioAPIInterface: lock_author = ctx.author if ctx else None async with self._lock: if lock_id in self._tasks: - if IS_DEBUG: - log.debug("Running database writes for %d (%s)", lock_id, lock_author) + log.trace("Running database writes for %d (%s)", lock_id, lock_author) try: tasks = self._tasks[lock_id] tasks = [self.route_tasks(a, tasks[a]) for a in tasks] await asyncio.gather(*tasks, return_exceptions=False) del self._tasks[lock_id] except Exception as exc: - debug_exc_log( - log, exc, "Failed database writes for %d (%s)", lock_id, lock_author + log.verbose( + "Failed database writes for %d (%s)", lock_id, lock_author, exc_info=exc ) else: - if IS_DEBUG: - log.debug("Completed database writes for %d (%s)", lock_id, lock_author) + log.trace("Completed database writes for %d (%s)", lock_id, lock_author) async def run_all_pending_tasks(self) -> None: """Run all pending tasks left in the cache, called on cog_unload.""" async with self._lock: - if IS_DEBUG: - log.debug("Running pending writes to database") + log.trace("Running pending writes to database") try: tasks: MutableMapping = {"update": [], "insert": [], "global": []} async for k, task in AsyncIter(self._tasks.items()): @@ -179,10 +175,9 @@ class AudioAPIInterface: await asyncio.gather(*coro_tasks, return_exceptions=False) except Exception as exc: - debug_exc_log(log, exc, "Failed database writes") + log.verbose("Failed database writes", exc_info=exc) else: - if IS_DEBUG: - log.debug("Completed pending writes to database have finished") + log.trace("Completed pending writes to database have finished") def append_task(self, ctx: commands.Context, event: str, task: Tuple, _id: int = None) -> None: """Add a task to the cache to be run later.""" @@ -248,18 +243,17 @@ class AudioAPIInterface: {"track": track_info} ) except Exception as exc: - debug_exc_log( - log, exc, "Failed to fetch %r from YouTube table", track_info + log.verbose( + "Failed to fetch %r from YouTube table", track_info, exc_info=exc ) - if val is None: try: val = await self.fetch_youtube_query( ctx, track_info, current_cache_level=current_cache_level ) - except YouTubeApiError as err: + except YouTubeApiError as exc: val = None - youtube_api_error = err.message + youtube_api_error = exc.message if youtube_cache and val: task = ("update", ("youtube", {"track": track_info})) self.append_task(ctx, *task) @@ -387,8 +381,8 @@ class AudioAPIInterface: {"uri": f"spotify:track:{uri}"} ) except Exception as exc: - debug_exc_log( - log, exc, "Failed to fetch 'spotify:track:%s' from Spotify table", uri + log.verbose( + "Failed to fetch 'spotify:track:%s' from Spotify table", uri, exc_info=exc ) val = None else: @@ -515,8 +509,8 @@ class AudioAPIInterface: {"track": track_info} ) except Exception as exc: - debug_exc_log( - log, exc, "Failed to fetch %r from YouTube table", track_info + log.verbose( + "Failed to fetch %r from YouTube table", track_info, exc_info=exc ) should_query_global = globaldb_toggle and query_global and val is None if should_query_global: @@ -531,9 +525,9 @@ class AudioAPIInterface: val = await self.fetch_youtube_query( ctx, track_info, current_cache_level=current_cache_level ) - except YouTubeApiError as err: + except YouTubeApiError as exc: val = None - youtube_api_error = err.message + youtube_api_error = exc.message skip_youtube_api = True if not youtube_api_error: if youtube_cache and val and llresponse is None: @@ -624,8 +618,7 @@ class AudioAPIInterface: query_obj=query, ): has_not_allowed = True - if IS_DEBUG: - log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) continue track_list.append(single_track) if enqueue: @@ -752,13 +745,13 @@ class AudioAPIInterface: try: (val, update) = await self.local_cache_api.youtube.fetch_one({"track": track_info}) except Exception as exc: - debug_exc_log(log, exc, "Failed to fetch %r from YouTube table", track_info) + log.verbose("Failed to fetch %r from YouTube table", track_info, exc_info=exc) if val is None: try: youtube_url = await self.fetch_youtube_query( ctx, track_info, current_cache_level=current_cache_level ) - except YouTubeApiError as err: + except YouTubeApiError: youtube_url = None else: if cache_enabled: @@ -817,11 +810,10 @@ class AudioAPIInterface: {"query": query_string} ) except Exception as exc: - debug_exc_log(log, exc, "Failed to fetch %r from Lavalink table", query_string) + log.verbose("Failed to fetch %r from Lavalink table", query_string, exc_info=exc) if val and isinstance(val, dict): - if IS_DEBUG: - log.debug("Updating Local Database with %r", query_string) + log.trace("Updating Local Database with %r", query_string) task = ("update", ("lavalink", {"query": query_string})) self.append_task(ctx, *task) else: @@ -854,8 +846,7 @@ class AudioAPIInterface: ]: valid_global_entry = True if valid_global_entry: - if IS_DEBUG: - log.debug("Querying Global DB api for %r", query) + log.trace("Querying Global DB api for %r", query) results, called_api = results, False if valid_global_entry: pass @@ -873,8 +864,7 @@ class AudioAPIInterface: results, called_api = await self.fetch_track(ctx, player, query, forced=True) valid_global_entry = False else: - if IS_DEBUG: - log.debug("Querying Lavalink api for %r", query_string) + log.trace("Querying Lavalink api for %r", query_string) called_api = True try: results = await player.load_tracks(query_string) @@ -924,11 +914,10 @@ class AudioAPIInterface: ) self.append_task(ctx, *task) except Exception as exc: - debug_exc_log( - log, - exc, + log.verbose( "Failed to enqueue write task for %r to Lavalink table", query_string, + exc_info=exc, ) return results, called_api @@ -952,7 +941,7 @@ class AudioAPIInterface: ) tracks = playlist.tracks_obj except Exception as exc: - debug_exc_log(log, exc, "Failed to fetch playlist for autoplay") + log.verbose("Failed to fetch playlist for autoplay", exc_info=exc) if not tracks or not getattr(playlist, "tracks", None): if cache_enabled: @@ -991,10 +980,9 @@ class AudioAPIInterface: f"{track.title} {track.author} {track.uri} {query}", query_obj=query, ): - if IS_DEBUG: - log.debug( - "Query is not allowed in %r (%d)", player.guild.name, player.guild.id - ) + log.debug( + "Query is not allowed in %r (%d)", player.guild.name, player.guild.id + ) continue valid = True track.extras.update( diff --git a/redbot/cogs/audio/apis/local_db.py b/redbot/cogs/audio/apis/local_db.py index d8dcf9dbd..913eb0eaf 100644 --- a/redbot/cogs/audio/apis/local_db.py +++ b/redbot/cogs/audio/apis/local_db.py @@ -16,7 +16,6 @@ from redbot.core.i18n import Translator from redbot.core.utils import AsyncIter from redbot.core.utils.dbtools import APSWConnectionWrapper -from ..audio_logging import debug_exc_log from ..sql_statements import ( LAVALINK_CREATE_INDEX, LAVALINK_CREATE_TABLE, @@ -124,7 +123,7 @@ class BaseWrapper: current_version = row_result.fetchone() break except Exception as exc: - debug_exc_log(log, exc, "Failed to completed fetch from database") + log.verbose("Failed to completed fetch from database", exc_info=exc) if isinstance(current_version, tuple): current_version = current_version[0] if current_version == _SCHEMA_VERSION: @@ -141,7 +140,7 @@ class BaseWrapper: with self.database.transaction() as transaction: transaction.executemany(self.statement.upsert, values) except Exception as exc: - debug_exc_log(log, exc, "Error during table insert") + log.trace("Error during table insert", exc_info=exc) async def update(self, values: MutableMapping) -> None: """Update an entry of the local cache""" @@ -152,7 +151,7 @@ class BaseWrapper: with concurrent.futures.ThreadPoolExecutor(max_workers=1) as executor: executor.submit(self.database.cursor().execute, self.statement.update, values) except Exception as exc: - debug_exc_log(log, exc, "Error during table update") + log.verbose("Error during table update", exc_info=exc) async def _fetch_one( self, values: MutableMapping @@ -173,7 +172,7 @@ class BaseWrapper: row_result = future.result() row = row_result.fetchone() except Exception as exc: - debug_exc_log(log, exc, "Failed to completed fetch from database") + log.verbose("Failed to completed fetch from database", exc_info=exc) if not row: return None if self.fetch_result is None: @@ -195,7 +194,7 @@ class BaseWrapper: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to completed fetch from database") + log.verbose("Failed to completed fetch from database", exc_info=exc) async for row in AsyncIter(row_result): output.append(self.fetch_result(*row)) return output @@ -223,7 +222,7 @@ class BaseWrapper: else: row = None except Exception as exc: - debug_exc_log(log, exc, "Failed to completed random fetch from database") + log.verbose("Failed to completed random fetch from database", exc_info=exc) if not row: return None if self.fetch_result is None: @@ -353,7 +352,7 @@ class LavalinkTableWrapper(BaseWrapper): try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to completed fetch from database") + log.verbose("Failed to completed fetch from database", exc_info=exc) async for row in AsyncIter(row_result): output.append(self.fetch_for_global(*row)) return output diff --git a/redbot/cogs/audio/apis/persist_queue_wrapper.py b/redbot/cogs/audio/apis/persist_queue_wrapper.py index 7fe802803..d03ab831a 100644 --- a/redbot/cogs/audio/apis/persist_queue_wrapper.py +++ b/redbot/cogs/audio/apis/persist_queue_wrapper.py @@ -16,7 +16,6 @@ from redbot.core.i18n import Translator from redbot.core.utils import AsyncIter from redbot.core.utils.dbtools import APSWConnectionWrapper -from ..audio_logging import debug_exc_log from ..sql_statements import ( PERSIST_QUEUE_BULK_PLAYED, PERSIST_QUEUE_CREATE_INDEX, @@ -90,7 +89,7 @@ class QueueInterface: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to complete playlist fetch from database") + log.verbose("Failed to complete playlist fetch from database", exc_info=exc) return [] async for index, row in AsyncIter(row_result).enumerate(start=1): diff --git a/redbot/cogs/audio/apis/playlist_wrapper.py b/redbot/cogs/audio/apis/playlist_wrapper.py index 0a884ef18..03b042066 100644 --- a/redbot/cogs/audio/apis/playlist_wrapper.py +++ b/redbot/cogs/audio/apis/playlist_wrapper.py @@ -12,7 +12,6 @@ from redbot.core.i18n import Translator from redbot.core.utils import AsyncIter from redbot.core.utils.dbtools import APSWConnectionWrapper -from ..audio_logging import debug_exc_log from ..sql_statements import ( HANDLE_DISCORD_DATA_DELETION_QUERY, PLAYLIST_CREATE_INDEX, @@ -109,7 +108,7 @@ class PlaylistWrapper: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to complete playlist fetch from database") + log.verbose("Failed to complete playlist fetch from database", exc_info=exc) return None row = row_result.fetchone() if row: @@ -142,7 +141,9 @@ class PlaylistWrapper: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to complete playlist fetch from database") + log.verbose( + "Failed to complete playlist fetch from database", exc_info=exc + ) return [] else: for future in concurrent.futures.as_completed( @@ -157,7 +158,9 @@ class PlaylistWrapper: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to complete playlist fetch from database") + log.verbose( + "Failed to complete playlist fetch from database", exc_info=exc + ) return [] async for row in AsyncIter(row_result): output.append(PlaylistFetchResult(*row)) @@ -171,7 +174,7 @@ class PlaylistWrapper: try: playlist_id = int(playlist_id) except Exception as exc: - debug_exc_log(log, exc, "Failed converting playlist_id to int") + log.verbose("Failed converting playlist_id to int", exc_info=exc) playlist_id = -1 output = [] @@ -194,7 +197,7 @@ class PlaylistWrapper: try: row_result = future.result() except Exception as exc: - debug_exc_log(log, exc, "Failed to complete fetch from database") + log.verbose("Failed to complete fetch from database", exc_info=exc) return [] async for row in AsyncIter(row_result): diff --git a/redbot/cogs/audio/apis/spotify.py b/redbot/cogs/audio/apis/spotify.py index 808effb5b..f7fbfd911 100644 --- a/redbot/cogs/audio/apis/spotify.py +++ b/redbot/cogs/audio/apis/spotify.py @@ -102,7 +102,7 @@ class SpotifyWrapper: async with self.session.request("GET", url, params=params, headers=headers) as r: data = await r.json(loads=json.loads) if r.status != 200: - log.debug("Issue making GET request to %r: [%d] %r", url, r.status, data) + log.verbose("Issue making GET request to %r: [%d] %r", url, r.status, data) return data async def update_token(self, new_token: Mapping[str, str]): @@ -156,7 +156,7 @@ class SpotifyWrapper: async with self.session.post(url, data=payload, headers=headers) as r: data = await r.json(loads=json.loads) if r.status != 200: - log.debug("Issue making POST request to %r: [%d] %r", url, r.status, data) + log.verbose("Issue making POST request to %r: [%d] %r", url, r.status, data) return data async def make_get_call(self, url: str, params: MutableMapping) -> MutableMapping: diff --git a/redbot/cogs/audio/audio_logging.py b/redbot/cogs/audio/audio_logging.py deleted file mode 100644 index 7e108aaa0..000000000 --- a/redbot/cogs/audio/audio_logging.py +++ /dev/null @@ -1,18 +0,0 @@ -import logging -import sys - -from typing import Final, Any, Tuple - -IS_DEBUG: Final[bool] = "--debug" in sys.argv - - -def is_debug() -> bool: - return IS_DEBUG - - -def debug_exc_log(lg: logging.Logger, exc: Exception, msg: str = None, *args: Tuple[Any]) -> None: - """Logs an exception if logging is set to DEBUG level""" - if lg.getEffectiveLevel() <= logging.DEBUG: - if msg is None: - msg = f"{exc}" - lg.exception(msg, *args, exc_info=exc) diff --git a/redbot/cogs/audio/converters.py b/redbot/cogs/audio/converters.py index ea5ce66bf..2b4cc4f52 100644 --- a/redbot/cogs/audio/converters.py +++ b/redbot/cogs/audio/converters.py @@ -248,10 +248,10 @@ class ScopeParser(commands.Converter): guild_raw = " ".join(guild).strip() try: target_guild = await global_unique_guild_finder(ctx, guild_raw) - except TooManyMatches as err: - server_error = f"{err}\n" - except NoMatchesFound as err: - server_error = f"{err}\n" + except TooManyMatches as exc: + server_error = f"{exc}\n" + except NoMatchesFound as exc: + server_error = f"{exc}\n" if target_guild is None: raise commands.ArgParserFailure( "--guild", guild_raw, custom_help=f"{server_error}{_(_GUILD_HELP)}" @@ -270,10 +270,10 @@ class ScopeParser(commands.Converter): try: target_user = await global_unique_user_finder(ctx, user_raw, guild=target_guild) specified_user = True - except TooManyMatches as err: - user_error = f"{err}\n" - except NoMatchesFound as err: - user_error = f"{err}\n" + except TooManyMatches as exc: + user_error = f"{exc}\n" + except NoMatchesFound as exc: + user_error = f"{exc}\n" if target_user is None: raise commands.ArgParserFailure( @@ -386,10 +386,10 @@ class ComplexScopeParser(commands.Converter): to_guild_raw = " ".join(to_guild).strip() try: target_guild = await global_unique_guild_finder(ctx, to_guild_raw) - except TooManyMatches as err: - target_server_error = f"{err}\n" - except NoMatchesFound as err: - target_server_error = f"{err}\n" + except TooManyMatches as exc: + target_server_error = f"{exc}\n" + except NoMatchesFound as exc: + target_server_error = f"{exc}\n" if target_guild is None: raise commands.ArgParserFailure( "--to-guild", @@ -412,10 +412,10 @@ class ComplexScopeParser(commands.Converter): from_guild_raw = " ".join(from_guild).strip() try: source_guild = await global_unique_guild_finder(ctx, from_guild_raw) - except TooManyMatches as err: - source_server_error = f"{err}\n" - except NoMatchesFound as err: - source_server_error = f"{err}\n" + except TooManyMatches as exc: + source_server_error = f"{exc}\n" + except NoMatchesFound as exc: + source_server_error = f"{exc}\n" if source_guild is None: raise commands.ArgParserFailure( "--from-guild", @@ -441,10 +441,10 @@ class ComplexScopeParser(commands.Converter): try: target_user = await global_unique_user_finder(ctx, to_user_raw, guild=target_guild) specified_target_user = True - except TooManyMatches as err: - target_user_error = f"{err}\n" - except NoMatchesFound as err: - target_user_error = f"{err}\n" + except TooManyMatches as exc: + target_user_error = f"{exc}\n" + except NoMatchesFound as exc: + target_user_error = f"{exc}\n" if target_user is None: raise commands.ArgParserFailure( "--to-author", to_user_raw, custom_help=f"{target_user_error}{_(_USER_HELP)}" @@ -466,10 +466,10 @@ class ComplexScopeParser(commands.Converter): ctx, from_user_raw, guild=target_guild ) specified_target_user = True - except TooManyMatches as err: - source_user_error = f"{err}\n" - except NoMatchesFound as err: - source_user_error = f"{err}\n" + except TooManyMatches as exc: + source_user_error = f"{exc}\n" + except NoMatchesFound as exc: + source_user_error = f"{exc}\n" if source_user is None: raise commands.ArgParserFailure( "--from-author", diff --git a/redbot/cogs/audio/core/commands/controller.py b/redbot/cogs/audio/core/commands/controller.py index 795a6cf8e..1135625ff 100644 --- a/redbot/cogs/audio/core/commands/controller.py +++ b/redbot/cogs/audio/core/commands/controller.py @@ -1,6 +1,5 @@ import asyncio import contextlib -import datetime import logging import time from pathlib import Path diff --git a/redbot/cogs/audio/core/commands/player.py b/redbot/cogs/audio/core/commands/player.py index 70f31f6b5..828392f40 100644 --- a/redbot/cogs/audio/core/commands/player.py +++ b/redbot/cogs/audio/core/commands/player.py @@ -1,5 +1,4 @@ import contextlib -import datetime import logging import math import time @@ -18,7 +17,6 @@ from redbot.core.utils import AsyncIter from redbot.core.utils.menus import DEFAULT_CONTROLS, close_menu, menu, next_page, prev_page from ...audio_dataclasses import _PARTIALLY_SUPPORTED_MUSIC_EXT, Query -from ...audio_logging import IS_DEBUG from ...errors import ( DatabaseError, QueryUnauthorized, @@ -129,9 +127,9 @@ class PlayerCommands(MixinMeta, metaclass=CompositeMetaClass): return await self._get_spotify_tracks(ctx, query) try: await self._enqueue_tracks(ctx, query) - except QueryUnauthorized as err: + except QueryUnauthorized as exc: return await self.send_embed_msg( - ctx, title=_("Unable To Play Tracks"), description=err.message + ctx, title=_("Unable To Play Tracks"), description=exc.message ) except Exception as e: self.update_player_lock(ctx, False) @@ -238,9 +236,9 @@ class PlayerCommands(MixinMeta, metaclass=CompositeMetaClass): tracks = await self._get_spotify_tracks(ctx, query) else: tracks = await self._enqueue_tracks(ctx, query, enqueue=False) - except QueryUnauthorized as err: + except QueryUnauthorized as exc: return await self.send_embed_msg( - ctx, title=_("Unable To Play Tracks"), description=err.message + ctx, title=_("Unable To Play Tracks"), description=exc.message ) except Exception as e: self.update_player_lock(ctx, False) @@ -287,8 +285,7 @@ class PlayerCommands(MixinMeta, metaclass=CompositeMetaClass): f"{single_track.title} {single_track.author} {single_track.uri} {str(query)}", query_obj=query, ): - if IS_DEBUG: - log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) self.update_player_lock(ctx, False) return await self.send_embed_msg( ctx, @@ -818,10 +815,7 @@ class PlayerCommands(MixinMeta, metaclass=CompositeMetaClass): f"{track.title} {track.author} {track.uri} " f"{str(query)}", query_obj=query, ): - if IS_DEBUG: - log.debug( - "Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id - ) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) continue elif guild_data["maxlength"] > 0: if self.is_track_length_allowed(track, guild_data["maxlength"]): diff --git a/redbot/cogs/audio/core/commands/playlists.py b/redbot/cogs/audio/core/commands/playlists.py index f8dbfafea..d5c7e6074 100644 --- a/redbot/cogs/audio/core/commands/playlists.py +++ b/redbot/cogs/audio/core/commands/playlists.py @@ -25,7 +25,6 @@ from redbot.core.utils.predicates import MessagePredicate from ...apis.api_utils import FakePlaylist from ...apis.playlist_interface import Playlist, create_playlist, delete_playlist, get_all_playlist from ...audio_dataclasses import LocalPath, Query -from ...audio_logging import IS_DEBUG, debug_exc_log from ...converters import ComplexScopeParser, ScopeParser from ...errors import MissingGuild, TooManyMatches, TrackEnqueueError from ...utils import PlaylistScope @@ -778,7 +777,7 @@ class PlaylistCommands(MixinMeta, metaclass=CompositeMetaClass): file=discord.File(str(temp_tar)), ) except Exception as exc: - debug_exc_log(log, exc, "Failed to send playlist to channel") + log.verbose("Failed to send playlist to channel", exc_info=exc) temp_file.unlink() temp_tar.unlink() else: @@ -1524,10 +1523,7 @@ class PlaylistCommands(MixinMeta, metaclass=CompositeMetaClass): f"{track.title} {track.author} {track.uri} " f"{str(query)}", query_obj=query, ): - if IS_DEBUG: - log.debug( - "Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id - ) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) continue query = Query.process_input(track.uri, self.local_folder_current_path) if query.is_local: diff --git a/redbot/cogs/audio/core/commands/queue.py b/redbot/cogs/audio/core/commands/queue.py index 375bdf9b5..9d3b0e06d 100644 --- a/redbot/cogs/audio/core/commands/queue.py +++ b/redbot/cogs/audio/core/commands/queue.py @@ -1,6 +1,5 @@ import asyncio import contextlib -import datetime import logging import math from pathlib import Path diff --git a/redbot/cogs/audio/core/events/cog.py b/redbot/cogs/audio/core/events/cog.py index 6c44c75b6..5b83064f4 100644 --- a/redbot/cogs/audio/core/events/cog.py +++ b/redbot/cogs/audio/core/events/cog.py @@ -13,7 +13,6 @@ from redbot.core import commands from redbot.core.i18n import Translator from ...apis.playlist_interface import Playlist, delete_playlist, get_playlist -from ...audio_logging import debug_exc_log from ...utils import PlaylistScope from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass @@ -123,8 +122,8 @@ class AudioEvents(MixinMeta, metaclass=CompositeMetaClass): playlist_api=self.playlist_api, bot=self.bot, ) - except Exception as err: - debug_exc_log(log, err, "Failed to delete daily playlist ID: %d", too_old_id) + except Exception as exc: + log.verbose("Failed to delete daily playlist ID: %d", too_old_id, exc_info=exc) try: await delete_playlist( scope=PlaylistScope.GLOBAL.value, @@ -134,9 +133,9 @@ class AudioEvents(MixinMeta, metaclass=CompositeMetaClass): playlist_api=self.playlist_api, bot=self.bot, ) - except Exception as err: - debug_exc_log( - log, err, "Failed to delete global daily playlist ID: %d", too_old_id + except Exception as exc: + log.verbose( + "Failed to delete global daily playlist ID: %d", too_old_id, exc_info=exc ) persist_cache = self._persist_queue_cache.setdefault( guild.id, await self.config.guild(guild).persist_queue() diff --git a/redbot/cogs/audio/core/events/dpy.py b/redbot/cogs/audio/core/events/dpy.py index 7a26a2035..e8f73b69a 100644 --- a/redbot/cogs/audio/core/events/dpy.py +++ b/redbot/cogs/audio/core/events/dpy.py @@ -12,14 +12,15 @@ import lavalink from aiohttp import ClientConnectorError from discord.ext.commands import CheckFailure + from redbot.core import commands from redbot.core.i18n import Translator from redbot.core.utils.chat_formatting import box, humanize_list -from ...audio_logging import debug_exc_log from ...errors import TrackEnqueueError from ..abc import MixinMeta from ..cog_utils import HUMANIZED_PERM, CompositeMetaClass +from ...utils import task_callback_trace log = logging.getLogger("red.cogs.Audio.cog.Events.dpy") _ = Translator("Audio", Path(__file__)) @@ -176,7 +177,7 @@ class DpyEvents(MixinMeta, metaclass=CompositeMetaClass): description=_("Connection to Lavalink has been lost."), error=True, ) - debug_exc_log(log, error, "This is a handled error") + log.trace("This is a handled error", exc_info=error) elif isinstance(error, KeyError) and "such player for that guild" in str(error): handled = True await self.send_embed_msg( @@ -185,7 +186,7 @@ class DpyEvents(MixinMeta, metaclass=CompositeMetaClass): description=_("The bot is not connected to a voice channel."), error=True, ) - debug_exc_log(log, error, "This is a handled error") + log.trace("This is a handled error", exc_info=error) elif isinstance(error, (TrackEnqueueError, asyncio.exceptions.TimeoutError)): handled = True await self.send_embed_msg( @@ -197,7 +198,7 @@ class DpyEvents(MixinMeta, metaclass=CompositeMetaClass): ), error=True, ) - debug_exc_log(log, error, "This is a handled error") + log.trace("This is a handled error", exc_info=error) elif isinstance(error, discord.errors.HTTPException): handled = True await self.send_embed_msg( @@ -229,7 +230,9 @@ class DpyEvents(MixinMeta, metaclass=CompositeMetaClass): if not self.cog_cleaned_up: self.bot.dispatch("red_audio_unload", self) self.session.detach() - self.bot.loop.create_task(self._close_database()) + self.bot.loop.create_task(self._close_database()).add_done_callback( + task_callback_trace + ) if self.player_automated_timer_task: self.player_automated_timer_task.cancel() @@ -244,9 +247,13 @@ class DpyEvents(MixinMeta, metaclass=CompositeMetaClass): lavalink.unregister_event_listener(self.lavalink_event_handler) lavalink.unregister_update_listener(self.lavalink_update_handler) - self.bot.loop.create_task(lavalink.close(self.bot)) + self.bot.loop.create_task(lavalink.close(self.bot)).add_done_callback( + task_callback_trace + ) if self.player_manager is not None: - self.bot.loop.create_task(self.player_manager.shutdown()) + self.bot.loop.create_task(self.player_manager.shutdown()).add_done_callback( + task_callback_trace + ) self.cog_cleaned_up = True diff --git a/redbot/cogs/audio/core/events/lavalink.py b/redbot/cogs/audio/core/events/lavalink.py index 1c947bb81..99d24e82e 100644 --- a/redbot/cogs/audio/core/events/lavalink.py +++ b/redbot/cogs/audio/core/events/lavalink.py @@ -14,6 +14,7 @@ from redbot.core.i18n import Translator, set_contextual_locales_from_guild from ...errors import DatabaseError, TrackEnqueueError from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass +from ...utils import task_callback_trace log = logging.getLogger("red.cogs.Audio.cog.Events.lavalink") ws_audio_log = logging.getLogger("red.Audio.WS.Audio") @@ -50,13 +51,13 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): guild_id = self.rgetattr(guild, "id", None) if not guild: return + log.debug("Received a new lavalink event for %d: %s: %r", guild_id, event_type, extra) guild_data = await self.config.guild(guild).all() disconnect = guild_data["disconnect"] if event_type == lavalink.LavalinkEvents.FORCED_DISCONNECT: self.bot.dispatch("red_audio_audio_disconnect", guild) self._ll_guild_updates.discard(guild.id) return - if event_type == lavalink.LavalinkEvents.WEBSOCKET_CLOSED: deafen = guild_data["auto_deafen"] event_channel_id = extra.get("channelID") @@ -67,6 +68,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): by_remote = extra.get("byRemote", "") reason = extra.get("reason", "No Specified Reason").strip() ws_audio_log.info( + "WS EVENT - SIMPLE RESUME (Healthy Socket) | " + "Voice websocket closed event " + "Code: %d -- Remote: %s -- %s", + extra.get("code"), + by_remote, + reason, + ) + ws_audio_log.debug( "WS EVENT - SIMPLE RESUME (Healthy Socket) | " "Voice websocket closed event " "Code: %d -- Remote: %s -- %s, %r", @@ -84,8 +93,12 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): await self._websocket_closed_handler( guild=guild, player=player, extra=extra, deafen=deafen, disconnect=disconnect ) - except Exception: - log.exception("Error in WEBSOCKET_CLOSED handling for guild: %s", player.guild.id) + except Exception as exc: + log.debug( + "Error in WEBSOCKET_CLOSED handling for guild: %s", + player.guild.id, + exc_info=exc, + ) return await set_contextual_locales_from_guild(self.bot, guild) @@ -102,7 +115,6 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): current_track, self.local_folder_current_path ) status = await self.config.status() - log.debug("Received a new lavalink event for %d: %s: %r", guild_id, event_type, extra) prev_song: lavalink.Track = player.fetch("prev_song") await self.maybe_reset_error_counter(player) @@ -195,12 +207,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): ) player.store("notify_message", notify_message) if event_type == lavalink.LavalinkEvents.TRACK_START and status: + log.debug("Track started for %s, updating bot status", guild_id) player_check = await self.get_active_player_count() await self.update_bot_presence(*player_check) if event_type == lavalink.LavalinkEvents.TRACK_END and status: await asyncio.sleep(1) if not player.is_playing: + log.debug("Track ended for %s, updating bot status", guild_id) player_check = await self.get_active_player_count() await self.update_bot_presence(*player_check) @@ -211,6 +225,9 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): if notify_channel and notify and self._has_notify_perms(notify_channel): await self.send_embed_msg(notify_channel, title=_("Queue ended.")) if disconnect: + log.debug( + "Queue ended for %s, Disconnecting bot due to configuration", guild_id + ) self.bot.dispatch("red_audio_audio_disconnect", guild) await self.config.guild_from_id( guild_id=guild_id @@ -220,6 +237,7 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): await player.disconnect() self._ll_guild_updates.discard(guild.id) if status: + log.debug("Queue ended for %s, updating bot status", guild_id) player_check = await self.get_active_player_count() await self.update_bot_presence(*player_check) @@ -261,6 +279,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): if message_channel: message_channel = self.bot.get_channel(message_channel) if early_exit: + log.warning( + "Audio detected multiple continuous errors during playback " + "- terminating the player for guild: %s.", + guild_id, + ) + log.verbose( + "Player has been terminated due to multiple playback failures: %r", player + ) embed = discord.Embed( colour=await self.bot.get_embed_color(message_channel), title=_("Multiple Errors Detected"), @@ -294,7 +320,7 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): if current_id: asyncio.create_task( self.api_interface.global_cache_api.report_invalid(current_id) - ) + ).add_done_callback(task_callback_trace) await message_channel.send(embed=embed) await player.skip() @@ -330,7 +356,7 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): if player.channel.id != event_channel_id: code = 4014 if event_channel_id != channel_id: - ws_audio_log.info( + ws_audio_log.debug( "Received an op code for a channel that is no longer valid; %d " "Reason: Error code %d & %s, %r", event_channel_id, @@ -347,7 +373,8 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): if code in (1000,) and has_perm and player.current and player.is_playing: player.store("resumes", player.fetch("resumes", 0) + 1) await player.resume(player.current, start=player.position, replace=True) - ws_audio_log.info( + ws_audio_log.info("Player resumed | Reason: Error code %d & %s", code, reason) + ws_audio_log.debug( "Player resumed | Reason: Error code %d & %s, %r", code, reason, player ) self._ws_op_codes[guild_id]._init(self._ws_op_codes[guild_id]._maxsize) @@ -359,7 +386,7 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): else: player._con_delay = ExponentialBackoff(base=1) delay = player._con_delay.delay() - ws_audio_log.warning( + ws_audio_log.debug( "YOU CAN IGNORE THIS UNLESS IT'S CONSISTENTLY REPEATING FOR THE SAME GUILD - " "Voice websocket closed for guild %d -> " "Socket Closed %s. " @@ -371,7 +398,7 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): reason, player, ) - ws_audio_log.debug( + ws_audio_log.info( "Reconnecting to channel %d in guild: %d | %.2fs", channel_id, guild_id, @@ -387,6 +414,10 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): await player.connect(deafen=deafen) await player.resume(player.current, start=player.position, replace=True) ws_audio_log.info( + "Voice websocket reconnected Reason: Error code %d & Currently playing", + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "Reason: Error code %d & Currently playing, %r", code, @@ -399,6 +430,10 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.current, start=player.position, replace=True, pause=True ) ws_audio_log.info( + "Voice websocket reconnected Reason: Error code %d & Currently Paused", + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "Reason: Error code %d & Currently Paused, %r", code, @@ -408,6 +443,11 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.store("resumes", player.fetch("resumes", 0) + 1) await player.connect(deafen=deafen) ws_audio_log.info( + "Voice websocket reconnected " + "Reason: Error code %d & Not playing, but auto disconnect disabled", + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "Reason: Error code %d & Not playing, but auto disconnect disabled, %r", code, @@ -417,6 +457,11 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): elif not has_perm: self.bot.dispatch("red_audio_audio_disconnect", guild) ws_audio_log.info( + "Voice websocket disconnected " + "Reason: Error code %d & Missing permissions", + code, + ) + ws_audio_log.debug( "Voice websocket disconnected " "Reason: Error code %d & Missing permissions, %r", code, @@ -432,6 +477,9 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): else: self.bot.dispatch("red_audio_audio_disconnect", guild) ws_audio_log.info( + "Voice websocket disconnected Reason: Error code %d & Unknown", code + ) + ws_audio_log.debug( "Voice websocket disconnected Reason: Error code %d & Unknown, %r", code, player, @@ -447,7 +495,8 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.store("resumes", player.fetch("resumes", 0) + 1) await player.connect(deafen=deafen) await player.resume(player.current, start=player.position, replace=True) - ws_audio_log.info( + ws_audio_log.info("Player resumed - Reason: Error code %d & %s", code, reason) + ws_audio_log.debug( "Player resumed - Reason: Error code %d & %s, %r", code, reason, player ) elif code in (4015, 4009, 4006, 4000, 1006): @@ -464,6 +513,10 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): await player.connect(deafen=deafen) await player.resume(player.current, start=player.position, replace=True) ws_audio_log.info( + "Voice websocket reconnected Reason: Error code %d & Player is active", + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "Reason: Error code %d & Player is active, %r", code, @@ -476,6 +529,10 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.current, start=player.position, replace=True, pause=True ) ws_audio_log.info( + "Voice websocket reconnected Reason: Error code %d & Player is paused", + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "Reason: Error code %d & Player is paused, %r", code, @@ -485,6 +542,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.store("resumes", player.fetch("resumes", 0) + 1) await player.connect(deafen=deafen) ws_audio_log.info( + "Voice websocket reconnected " + "to channel %d in guild: %d | " + "Reason: Error code %d & Not playing", + channel_id, + guild_id, + code, + ) + ws_audio_log.debug( "Voice websocket reconnected " "to channel %d in guild: %d | " "Reason: Error code %d & Not playing, %r", @@ -497,6 +562,11 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): elif not has_perm: self.bot.dispatch("red_audio_audio_disconnect", guild) ws_audio_log.info( + "Voice websocket disconnected " + "Reason: Error code %d & Missing permissions", + code, + ) + ws_audio_log.debug( "Voice websocket disconnected " "Reason: Error code %d & Missing permissions, %r", code, @@ -514,6 +584,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): player.store("resumes", player.fetch("resumes", 0) + 1) await player.resume(player.current, start=player.position, replace=True) ws_audio_log.info( + "WS EVENT - SIMPLE RESUME (Healthy Socket) | " + "Voice websocket closed event " + "Code: %d -- Remote: %s -- %s", + code, + by_remote, + reason, + ) + ws_audio_log.debug( "WS EVENT - SIMPLE RESUME (Healthy Socket) | " "Voice websocket closed event " "Code: %d -- Remote: %s -- %s, %r", @@ -524,6 +602,14 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): ) else: ws_audio_log.info( + "WS EVENT - IGNORED (Healthy Socket) | " + "Voice websocket closed event " + "Code: %d -- Remote: %s -- %s", + code, + by_remote, + reason, + ) + ws_audio_log.debug( "WS EVENT - IGNORED (Healthy Socket) | " "Voice websocket closed event " "Code: %d -- Remote: %s -- %s, %r", @@ -532,8 +618,8 @@ class LavalinkEvents(MixinMeta, metaclass=CompositeMetaClass): reason, player, ) - except Exception: - log.exception("Error in task") + except Exception as exc: + log.exception("Error in task", exc_info=exc) finally: self._ws_op_codes[guild_id]._init(self._ws_op_codes[guild_id]._maxsize) self._ws_resume[guild_id].set() diff --git a/redbot/cogs/audio/core/tasks/lavalink.py b/redbot/cogs/audio/core/tasks/lavalink.py index 6135e62e9..c7e9a75bd 100644 --- a/redbot/cogs/audio/core/tasks/lavalink.py +++ b/redbot/cogs/audio/core/tasks/lavalink.py @@ -10,6 +10,7 @@ from ...errors import LavalinkDownloadFailed from ...manager import ServerManager from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass +from ...utils import task_callback_debug log = logging.getLogger("red.cogs.Audio.cog.Tasks.lavalink") _ = Translator("Audio", Path(__file__)) @@ -28,6 +29,7 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): lavalink.register_event_listener(self.lavalink_event_handler) lavalink.register_update_listener(self.lavalink_update_handler) self.lavalink_connect_task = self.bot.loop.create_task(self.lavalink_attempt_connect()) + self.lavalink_connect_task.add_done_callback(task_callback_debug) async def lavalink_attempt_connect(self, timeout: int = 50) -> None: self.lavalink_connection_aborted = False @@ -63,10 +65,10 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): exc_info=exc, ) self.lavalink_connection_aborted = True - raise + return except asyncio.CancelledError: - log.exception("Invalid machine architecture, cannot run Lavalink.") - raise + log.critical("Invalid machine architecture, cannot run Lavalink.") + return except Exception as exc: log.exception( "Unhandled exception whilst starting internal Lavalink server, " @@ -74,7 +76,7 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): exc_info=exc, ) self.lavalink_connection_aborted = True - raise + return else: break else: @@ -104,7 +106,7 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): resume_key=f"Red-Core-Audio-{self.bot.user.id}-{data_manager.instance_name}", ) except asyncio.TimeoutError: - log.error("Connecting to Lavalink server timed out, retrying...") + log.warning("Connecting to Lavalink server timed out, retrying...") if external is False and self.player_manager is not None: await self.player_manager.shutdown() retry_count += 1 @@ -114,7 +116,7 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): "Unhandled exception whilst connecting to Lavalink, aborting...", exc_info=exc ) self.lavalink_connection_aborted = True - raise + return else: break else: @@ -127,3 +129,4 @@ class LavalinkTasks(MixinMeta, metaclass=CompositeMetaClass): if external: await asyncio.sleep(5) self._restore_task = asyncio.create_task(self.restore_players()) + self._restore_task.add_done_callback(task_callback_debug) diff --git a/redbot/cogs/audio/core/tasks/player.py b/redbot/cogs/audio/core/tasks/player.py index c873300f2..684b79ab3 100644 --- a/redbot/cogs/audio/core/tasks/player.py +++ b/redbot/cogs/audio/core/tasks/player.py @@ -10,7 +10,6 @@ import lavalink from redbot.core.i18n import Translator from redbot.core.utils import AsyncIter -from ...audio_logging import debug_exc_log from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass @@ -36,8 +35,8 @@ class PlayerTasks(MixinMeta, metaclass=CompositeMetaClass): if p.paused and server.id in pause_times: try: await p.pause(False) - except Exception as err: - debug_exc_log(log, err, "Exception raised in Audio's unpausing %r.", p) + except Exception as exc: + log.debug("Exception raised in Audio's unpausing %r.", p, exc_info=exc) pause_times.pop(server.id, None) servers = stop_times.copy() servers.update(pause_times) @@ -55,9 +54,9 @@ class PlayerTasks(MixinMeta, metaclass=CompositeMetaClass): await self.config.guild_from_id( guild_id=sid ).currently_auto_playing_in.set([]) - except Exception as err: - debug_exc_log( - log, err, "Exception raised in Audio's emptydc_timer for %s.", sid + except Exception as exc: + log.debug( + "Exception raised in Audio's emptydc_timer for %s.", sid, exc_info=exc ) elif sid in stop_times and await self.config.guild(server_obj).emptydc_enabled(): @@ -73,11 +72,13 @@ class PlayerTasks(MixinMeta, metaclass=CompositeMetaClass): await self.config.guild_from_id( guild_id=sid ).currently_auto_playing_in.set([]) - except Exception as err: - if "No such player for that guild" in str(err): + except Exception as exc: + if "No such player for that guild" in str(exc): stop_times.pop(sid, None) - debug_exc_log( - log, err, "Exception raised in Audio's emptydc_timer for %s.", sid + log.debug( + "Exception raised in Audio's emptydc_timer for %s.", + sid, + exc_info=exc, ) elif ( sid in pause_times and await self.config.guild(server_obj).emptypause_enabled() @@ -86,10 +87,10 @@ class PlayerTasks(MixinMeta, metaclass=CompositeMetaClass): if (time.time() - pause_times.get(sid, 0)) >= emptypause_timer: try: await lavalink.get_player(sid).pause() - except Exception as err: - if "No such player for that guild" in str(err): + except Exception as exc: + if "No such player for that guild" in str(exc): pause_times.pop(sid, None) - debug_exc_log( - log, err, "Exception raised in Audio's pausing for %s.", sid + log.debug( + "Exception raised in Audio's pausing for %s.", sid, exc_info=exc ) await asyncio.sleep(5) diff --git a/redbot/cogs/audio/core/tasks/startup.py b/redbot/cogs/audio/core/tasks/startup.py index 66f3aa613..db5991d92 100644 --- a/redbot/cogs/audio/core/tasks/startup.py +++ b/redbot/cogs/audio/core/tasks/startup.py @@ -1,5 +1,4 @@ import asyncio -import datetime import itertools import logging from pathlib import Path @@ -11,16 +10,14 @@ import lavalink from redbot.core.data_manager import cog_data_path from redbot.core.i18n import Translator from redbot.core.utils import AsyncIter -from redbot.core.utils._internal_utils import send_to_owners_with_prefix_replaced from redbot.core.utils.dbtools import APSWConnectionWrapper from ...apis.interface import AudioAPIInterface from ...apis.playlist_wrapper import PlaylistWrapper -from ...audio_logging import debug_exc_log from ...errors import DatabaseError, TrackEnqueueError -from ...utils import task_callback +from ...utils import task_callback_debug from ..abc import MixinMeta -from ..cog_utils import _OWNER_NOTIFICATION, _SCHEMA_VERSION, CompositeMetaClass +from ..cog_utils import _SCHEMA_VERSION, CompositeMetaClass log = logging.getLogger("red.cogs.Audio.cog.Tasks.startup") _ = Translator("Audio", Path(__file__)) @@ -33,7 +30,7 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): # as initial load happens before the bot can ever be ready. lavalink.set_logging_level(self.bot._cli_flags.logging_level) self.cog_init_task = self.bot.loop.create_task(self.initialize()) - self.cog_init_task.add_done_callback(task_callback) + self.cog_init_task.add_done_callback(task_callback_debug) async def initialize(self) -> None: await self.bot.wait_until_red_ready() @@ -59,21 +56,21 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): self.player_automated_timer_task = self.bot.loop.create_task( self.player_automated_timer() ) - self.player_automated_timer_task.add_done_callback(task_callback) - except Exception as err: - log.exception("Audio failed to start up, please report this issue.", exc_info=err) - raise err + self.player_automated_timer_task.add_done_callback(task_callback_debug) + except Exception as exc: + log.critical("Audio failed to start up, please report this issue.", exc_info=exc) + return self.cog_ready_event.set() async def restore_players(self): tries = 0 tracks_to_restore = await self.api_interface.persistent_queue_api.fetch_all() - while not lavalink.node._nodes: + while not lavalink.get_all_nodes(): await asyncio.sleep(1) tries += 1 if tries > 60: - log.exception("Unable to restore players, couldn't connect to Lavalink.") + log.warning("Unable to restore players, couldn't connect to Lavalink.") return metadata = {} all_guilds = await self.config.all_guilds() @@ -136,8 +133,8 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): tries += 1 except Exception as exc: tries += 1 - debug_exc_log( - log, exc, "Failed to restore music voice channel %s", vc_id + log.debug( + "Failed to restore music voice channel %s", vc_id, exc_info=exc ) if vc is None: break @@ -159,9 +156,9 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): player.maybe_shuffle() if not player.is_playing: await player.play() - log.info("Restored %r", player) - except Exception as err: - debug_exc_log(log, err, "Error restoring player in %d", guild_id) + log.debug("Restored %r", player) + except Exception as exc: + log.debug("Error restoring player in %d", guild_id, exc_info=exc) await self.api_interface.persistent_queue_api.drop(guild_id) for guild_id, (notify_channel_id, vc_id) in metadata.items(): @@ -205,7 +202,7 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): tries += 1 except Exception as exc: tries += 1 - debug_exc_log(log, exc, "Failed to restore music voice channel %s", vc_id) + log.debug("Failed to restore music voice channel %s", vc_id, exc_info=exc) if vc is None: break else: @@ -219,7 +216,7 @@ class StartUpTasks(MixinMeta, metaclass=CompositeMetaClass): if player.volume != volume: await player.set_volume(volume) player.maybe_shuffle() - log.info("Restored %r", player) + log.debug("Restored %r", player) if not player.is_playing: notify_channel = player.fetch("notify_channel") try: diff --git a/redbot/cogs/audio/core/utilities/formatting.py b/redbot/cogs/audio/core/utilities/formatting.py index b4a1fa1f1..3e976197d 100644 --- a/redbot/cogs/audio/core/utilities/formatting.py +++ b/redbot/cogs/audio/core/utilities/formatting.py @@ -1,4 +1,3 @@ -import datetime import logging import math import re @@ -17,7 +16,6 @@ from redbot.core.utils import AsyncIter from redbot.core.utils.chat_formatting import box, escape from ...audio_dataclasses import LocalPath, Query -from ...audio_logging import IS_DEBUG from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass @@ -163,8 +161,7 @@ class FormattingUtilities(MixinMeta, metaclass=CompositeMetaClass): f"{search_choice.title} {search_choice.author} {search_choice.uri} {str(query)}", query_obj=query, ): - if IS_DEBUG: - log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) self.update_player_lock(ctx, False) return await self.send_embed_msg( ctx, title=_("This track is not allowed in this server.") diff --git a/redbot/cogs/audio/core/utilities/miscellaneous.py b/redbot/cogs/audio/core/utilities/miscellaneous.py index cd50b6a26..72bc4a142 100644 --- a/redbot/cogs/audio/core/utilities/miscellaneous.py +++ b/redbot/cogs/audio/core/utilities/miscellaneous.py @@ -20,7 +20,7 @@ from redbot.core.utils import AsyncIter from redbot.core.utils.chat_formatting import humanize_number from ...apis.playlist_interface import get_all_playlist_for_migration23 -from ...utils import PlaylistScope, task_callback +from ...utils import PlaylistScope, task_callback_trace from ..abc import MixinMeta from ..cog_utils import CompositeMetaClass, DataReader @@ -36,7 +36,7 @@ class MiscellaneousUtilities(MixinMeta, metaclass=CompositeMetaClass): ) -> asyncio.Task: """Non blocking version of clear_react.""" task = self.bot.loop.create_task(self.clear_react(message, emoji)) - task.add_done_callback(task_callback) + task.add_done_callback(task_callback_trace) return task async def maybe_charge_requester(self, ctx: commands.Context, jukebox_price: int) -> bool: diff --git a/redbot/cogs/audio/core/utilities/player.py b/redbot/cogs/audio/core/utilities/player.py index ced9788e4..d905d6988 100644 --- a/redbot/cogs/audio/core/utilities/player.py +++ b/redbot/cogs/audio/core/utilities/player.py @@ -15,7 +15,6 @@ from redbot.core.utils import AsyncIter from redbot.core.utils.chat_formatting import bold, escape from ...audio_dataclasses import _PARTIALLY_SUPPORTED_MUSIC_EXT, Query -from ...audio_logging import IS_DEBUG, debug_exc_log from ...errors import QueryUnauthorized, SpotifyFetchError, TrackEnqueueError from ...utils import Notifier from ..abc import MixinMeta @@ -122,8 +121,8 @@ class PlayerUtilities(MixinMeta, metaclass=CompositeMetaClass): player = lavalink.get_player(ctx.guild.id) log.debug("Current requester is %s", player.current.requester) return player.current.requester.id == member.id - except Exception as err: - debug_exc_log(log, err, "Caught error in `is_requester`") + except Exception as exc: + log.trace("Caught error in `is_requester`", exc_info=exc) return False async def _skip_action(self, ctx: commands.Context, skip_to_track: int = None) -> None: @@ -451,8 +450,7 @@ class PlayerUtilities(MixinMeta, metaclass=CompositeMetaClass): f"{track.title} {track.author} {track.uri} " f"{str(query)}", query_obj=query, ): - if IS_DEBUG: - log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) continue elif guild_data["maxlength"] > 0: if self.is_track_length_allowed(track, guild_data["maxlength"]): @@ -541,8 +539,7 @@ class PlayerUtilities(MixinMeta, metaclass=CompositeMetaClass): ), query_obj=query, ): - if IS_DEBUG: - log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) + log.debug("Query is not allowed in %r (%d)", ctx.guild.name, ctx.guild.id) self.update_player_lock(ctx, False) return await self.send_embed_msg( ctx, title=_("This track is not allowed in this server.") diff --git a/redbot/cogs/audio/core/utilities/playlists.py b/redbot/cogs/audio/core/utilities/playlists.py index 28f285a55..a07723dab 100644 --- a/redbot/cogs/audio/core/utilities/playlists.py +++ b/redbot/cogs/audio/core/utilities/playlists.py @@ -24,7 +24,6 @@ from redbot.core.utils.predicates import ReactionPredicate from ...apis.playlist_interface import Playlist, PlaylistCompat23, create_playlist from ...audio_dataclasses import _PARTIALLY_SUPPORTED_MUSIC_EXT, Query -from ...audio_logging import debug_exc_log from ...errors import TooManyMatches, TrackEnqueueError from ...utils import Notifier, PlaylistScope from ..abc import MixinMeta @@ -434,15 +433,15 @@ class PlaylistUtilities(MixinMeta, metaclass=CompositeMetaClass): raise e track = result.tracks[0] - except Exception as err: - debug_exc_log(log, err, "Failed to get track for %r", song_url) + except Exception as exc: + log.verbose("Failed to get track for %r", song_url, exc_info=exc) continue try: track_obj = self.get_track_json(player, other_track=track) track_list.append(track_obj) successful_count += 1 - except Exception as err: - debug_exc_log(log, err, "Failed to create track for %r", track) + except Exception as exc: + log.verbose("Failed to create track for %r", track, exc_info=exc) continue if (track_count % 2 == 0) or (track_count == len(uploaded_track_list)): await notifier.notify_user( @@ -695,8 +694,10 @@ class PlaylistUtilities(MixinMeta, metaclass=CompositeMetaClass): return 0, [] try: data = json.loads(await response.read()) - except Exception: - log.exception("Curated playlist couldn't be parsed, report this error.") + except Exception as exc: + log.error( + "Curated playlist couldn't be parsed, report this error.", exc_info=exc + ) data = {} web_version = data.get("version", 0) entries = data.get("entries", []) diff --git a/redbot/cogs/audio/manager.py b/redbot/cogs/audio/manager.py index 3e7137fcd..9d37efb71 100644 --- a/redbot/cogs/audio/manager.py +++ b/redbot/cogs/audio/manager.py @@ -7,7 +7,6 @@ import pathlib import platform import re import shutil -import sys import tempfile import time from typing import ClassVar, Final, List, Optional, Pattern, Tuple @@ -19,7 +18,7 @@ from redbot.core import data_manager from redbot.core.i18n import Translator from .errors import LavalinkDownloadFailed -from .utils import task_callback +from .utils import task_callback_exception _ = Translator("Audio", pathlib.Path(__file__)) log = logging.getLogger("red.Audio.manager") @@ -167,7 +166,7 @@ class ServerManager: log.warning("Timeout occurred whilst waiting for internal Lavalink server to be ready") self._monitor_task = asyncio.create_task(self._monitor()) - self._monitor_task.add_done_callback(task_callback) + self._monitor_task.add_done_callback(task_callback_exception) async def _get_jar_args(self) -> List[str]: (java_available, java_version) = await self._has_java() @@ -251,7 +250,7 @@ class ServerManager: await asyncio.sleep(0.5) # This task hasn't been cancelled - Lavalink was shut down by something else - log.info("Internal Lavalink jar shutdown unexpectedly") + log.warning("Internal Lavalink jar shutdown unexpectedly") if not self._has_java_error(): log.info("Restarting internal Lavalink server") await self.start(self._java_exc) diff --git a/redbot/cogs/audio/utils.py b/redbot/cogs/audio/utils.py index e6d4ca4c9..6597109e6 100644 --- a/redbot/cogs/audio/utils.py +++ b/redbot/cogs/audio/utils.py @@ -216,12 +216,30 @@ class PlaylistScope(Enum): return list(map(lambda c: c.value, PlaylistScope)) -def task_callback(task: asyncio.Task) -> None: +def task_callback_exception(task: asyncio.Task) -> None: with contextlib.suppress(asyncio.CancelledError, asyncio.InvalidStateError): if exc := task.exception(): log.exception("%s raised an Exception", task.get_name(), exc_info=exc) +def task_callback_debug(task: asyncio.Task) -> None: + with contextlib.suppress(asyncio.CancelledError, asyncio.InvalidStateError): + if exc := task.exception(): + log.debug("%s raised an Exception", task.get_name(), exc_info=exc) + + +def task_callback_verbose(task: asyncio.Task) -> None: + with contextlib.suppress(asyncio.CancelledError, asyncio.InvalidStateError): + if exc := task.exception(): + log.verbose("%s raised an Exception", task.get_name(), exc_info=exc) + + +def task_callback_trace(task: asyncio.Task) -> None: + with contextlib.suppress(asyncio.CancelledError, asyncio.InvalidStateError): + if exc := task.exception(): + log.trace("%s raised an Exception", task.get_name(), exc_info=exc) + + def has_internal_server(): async def pred(ctx: commands.Context): external = await ctx.cog.config.use_external_lavalink()