Audio cleanup (#5618)

* add different logging level callbacks for task exception logging

* Add callback to tasks which didn't have them

* The boring stuff - (apply .trace() and .verbose() to audio, stop using debug_exc_log, delete audio_logging.py)

* Unsured import cleanup

* use new lavalink method

* return so it doesn't log this twice.

* improve logging on main event handler
This commit is contained in:
Draper
2022-03-16 16:42:17 +00:00
committed by GitHub
parent 593eeb5362
commit 2d9548ec0e
24 changed files with 301 additions and 241 deletions

View File

@@ -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):

View File

@@ -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(

View File

@@ -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

View File

@@ -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):

View File

@@ -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):

View File

@@ -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: