Rewrite logging

Add lots of log.info() statements
This commit is contained in:
Keith Edmunds 2023-12-17 00:12:03 +00:00
parent 2432039b72
commit 4b6c8b0634
9 changed files with 168 additions and 53 deletions

View File

@ -58,8 +58,8 @@ class Config(object):
HIDE_AFTER_PLAYING_OFFSET = 5000
INFO_TAB_TITLE_LENGTH = 15
LAST_PLAYED_TODAY_STRING = "Today"
LOG_LEVEL_STDERR = logging.ERROR
LOG_LEVEL_SYSLOG = logging.DEBUG
LOG_LEVEL_STDERR = logging.INFO
LOG_LEVEL_SYSLOG = logging.INFO
LOG_NAME = "musicmuster"
MAIL_PASSWORD = os.environ.get("MAIL_PASSWORD")
MAIL_PORT = int(os.environ.get("MAIL_PORT") or 25)

View File

@ -9,6 +9,7 @@ from PyQt6.QtWidgets import QTabWidget
from config import Config
from classes import MusicMusterSignals
from log import log
class InfoTabs(QTabWidget):
@ -37,6 +38,7 @@ class InfoTabs(QTabWidget):
"""Search Songfacts for title"""
slug = slugify(title, replacements=([["'", ""]]))
log.info(f"Songfacts Infotab for {title=}")
url = f"https://www.songfacts.com/search/songs/{slug}"
self.open_tab(url, title)
@ -45,6 +47,7 @@ class InfoTabs(QTabWidget):
"""Search Wikipedia for title"""
str = urllib.parse.quote_plus(title)
log.info(f"Wikipedia Infotab for {title=}")
url = f"https://www.wikipedia.org/w/index.php?search={str}"
self.open_tab(url, title)

View File

@ -1,5 +1,6 @@
#!/usr/bin/python3
import colorlog
import logging
import logging.handlers
import os
@ -22,50 +23,28 @@ class LevelTagFilter(logging.Filter):
return True
class DebugStdoutFilter(logging.Filter):
"""Filter debug messages sent to stdout"""
def filter(self, record: logging.LogRecord):
# Exceptions are logged at ERROR level
if record.levelno in [logging.DEBUG, logging.ERROR]:
return True
if record.module in Config.DEBUG_MODULES:
return True
if record.funcName in Config.DEBUG_FUNCTIONS:
return True
return False
log = logging.getLogger(Config.LOG_NAME)
log.setLevel(logging.DEBUG)
local_filter = LevelTagFilter()
# stderr
stderr = logging.StreamHandler()
stderr = colorlog.StreamHandler()
stderr.setLevel(Config.LOG_LEVEL_STDERR)
stderr.addFilter(local_filter)
stderr_fmt = colorlog.ColoredFormatter(
"%(log_color)s[%(asctime)s] %(leveltag)s: %(message)s", datefmt="%H:%M:%S"
)
stderr.setFormatter(stderr_fmt)
log.addHandler(stderr)
# syslog
syslog = logging.handlers.SysLogHandler(address="/dev/log")
syslog.setLevel(Config.LOG_LEVEL_SYSLOG)
# Filter
local_filter = LevelTagFilter()
debug_filter = DebugStdoutFilter()
syslog.addFilter(local_filter)
stderr.addFilter(local_filter)
stderr.addFilter(debug_filter)
stderr_fmt = logging.Formatter(
"[%(asctime)s] %(leveltag)s: %(message)s", datefmt="%H:%M:%S"
)
syslog_fmt = logging.Formatter(
"[%(name)s] %(module)s.%(funcName)s - %(leveltag)s: %(message)s"
"[%(name)s] %(filename)s:%(lineno)s %(leveltag)s: %(message)s"
)
stderr.setFormatter(stderr_fmt)
syslog.setFormatter(syslog_fmt)
log.addHandler(stderr)
log.addHandler(syslog)

View File

@ -66,6 +66,8 @@ class Music:
to hold up the UI during the fade.
"""
log.info("Music.stop()")
if not self.player:
return
@ -96,6 +98,8 @@ class Music:
Log and return if path not found.
"""
log.info(f"Music.play({path=}, {position=}")
if file_is_unreadable(path):
log.error(f"play({path}): path not readable")
return None
@ -125,6 +129,8 @@ class Music:
def stop(self) -> float:
"""Immediately stop playing"""
log.info("Music.stop()")
if not self.player:
return 0.0

View File

@ -561,6 +561,8 @@ class Window(QMainWindow, Ui_MainWindow):
) -> Optional[Playlists]:
"""Create new playlist"""
log.info(f"create_playlist({playlist_name=}")
playlist_name = self.solicit_playlist_name(session)
if not playlist_name:
return None
@ -569,6 +571,8 @@ class Window(QMainWindow, Ui_MainWindow):
if playlist:
playlist.mark_open()
return playlist
else:
log.error("Failed to create playlist")
return None
@ -586,7 +590,7 @@ class Window(QMainWindow, Ui_MainWindow):
add tab to display. Return index number of tab.
"""
assert playlist.id
log.info(f"create_playlist_tab({playlist=})")
playlist_tab = PlaylistTab(
musicmuster=self,
@ -594,6 +598,7 @@ class Window(QMainWindow, Ui_MainWindow):
)
idx = self.tabPlaylist.addTab(playlist_tab, playlist.name)
log.info(f"create_playlist_tab() returned: {idx=}")
return idx
def cut_rows(self) -> None:
@ -606,6 +611,8 @@ class Window(QMainWindow, Ui_MainWindow):
self.move_source_rows = self.active_tab().get_selected_rows()
self.move_source_model = self.active_proxy_model()
log.info(f"cut_rows(): {self.move_source_rows=} {self.move_source_model=}")
def debug(self):
"""Invoke debugger"""
@ -630,6 +637,8 @@ class Window(QMainWindow, Ui_MainWindow):
):
if self.close_playlist_tab():
playlist.delete(session)
else:
log.error("Failed to retrieve playlist")
def disable_play_next_controls(self) -> None:
"""
@ -680,6 +689,8 @@ class Window(QMainWindow, Ui_MainWindow):
so we need to disable it here while editing.
"""
log.info(f"enable_escape({enabled=})")
self.action_Clear_selection.setEnabled(enabled)
def enable_play_next_controls(self) -> None:
@ -844,6 +855,7 @@ class Window(QMainWindow, Ui_MainWindow):
proxy_model = self.active_proxy_model()
if proxy_model is None:
log.error("No proxy model")
return
# Get header text
@ -878,6 +890,7 @@ class Window(QMainWindow, Ui_MainWindow):
if playlist:
_ = self.create_playlist_tab(playlist)
playlist_ids.append(playlist.id)
log.info(f"load_last_playlists() loaded {playlist=}")
# Set active tab
record = Settings.get_int_settings(session, "active_tab")
if record.f_int is not None and record.f_int >= 0:
@ -986,6 +999,7 @@ class Window(QMainWindow, Ui_MainWindow):
if template:
playlist_name = self.solicit_playlist_name(session)
if not playlist_name:
log.error("Template has no name")
return
playlist = Playlists.create_playlist_from_template(
session, template, playlist_name
@ -996,6 +1010,7 @@ class Window(QMainWindow, Ui_MainWindow):
session.commit()
if playlist:
log.error("Playlist failed to create")
playlist.mark_open()
self.create_playlist_tab(playlist)
@ -1058,12 +1073,14 @@ class Window(QMainWindow, Ui_MainWindow):
- Update headers
"""
log.info(f"play_next({position=})")
# If there is no next track set, return.
if not track_sequence.next.track_id:
log.debug("musicmuster.play_next(): no next track selected")
log.error("musicmuster.play_next(): no next track selected")
return
if not track_sequence.next.path:
log.debug("musicmuster.play_next(): no path for next track")
log.error("musicmuster.play_next(): no path for next track")
return
# If there's currently a track playing, fade it.
@ -1083,12 +1100,13 @@ class Window(QMainWindow, Ui_MainWindow):
# Show closing volume graph
if track_sequence.now.fade_graph:
# TODO: remove if this is not a problem
stackprinter.format(show_vals="all")
track_sequence.now.fade_graph.plot()
else:
log.error("No fade_graph")
# Play (new) current track
if not track_sequence.now.path:
log.error("No path for next track")
return
track_sequence.now.start()
self.music.play(track_sequence.now.path, position)
@ -1167,8 +1185,11 @@ class Window(QMainWindow, Ui_MainWindow):
- If a track is playing, make that the next track
"""
log.info("resume()")
# Return if no saved position
if not track_sequence.previous.resume_marker:
log.error("No previous track position")
return
# We want to use play_next() to resume, so copy the previous
@ -1280,6 +1301,8 @@ class Window(QMainWindow, Ui_MainWindow):
playlist_tab = self.active_tab()
if playlist_tab:
playlist_tab.set_row_as_next_track()
else:
log.error("No active tab")
def set_tab_colour(self, widget: PlaylistTab, colour: QColor) -> None:
"""
@ -1389,6 +1412,7 @@ class Window(QMainWindow, Ui_MainWindow):
self.playing = False
else:
# Return if not playing
log.error("stop_playing() called but not playing")
return
# Stop/fade track
@ -1426,6 +1450,8 @@ class Window(QMainWindow, Ui_MainWindow):
def tab_change(self):
"""Called when active tab changed"""
log.info("tab_change()")
tab = self.active_tab()
if tab:
tab.resizeRowsToContents()

View File

@ -121,6 +121,8 @@ class PlaylistModel(QAbstractTableModel):
*args,
**kwargs,
):
log.info(f"PlaylistModel.__init__({playlist_id=})")
self.playlist_id = playlist_id
super().__init__(*args, **kwargs)
@ -152,6 +154,8 @@ class PlaylistModel(QAbstractTableModel):
Add track to existing header row
"""
log.info(f"add_track_to_header({row_number=}, {track_id=}, {note=}")
# Get existing row
try:
prd = self.playlist_rows[row_number]
@ -281,6 +285,8 @@ class PlaylistModel(QAbstractTableModel):
if plr:
plr.played = True
self.refresh_row(session, plr.plr_rownum)
else:
log.error(f"Can't retrieve plr, {track_sequence.now.plr_id=}")
# Update track times
self.start_end_times[row_number].start_time = track_sequence.now.start_time
@ -363,6 +369,8 @@ class PlaylistModel(QAbstractTableModel):
calls. To keep it simple, if inefficient, delete rows one by one.
"""
log.info(f"delete_rows({row_numbers=}")
with Session() as session:
for row_number in row_numbers:
super().beginRemoveRows(QModelIndex(), row_number, row_number)
@ -378,6 +386,8 @@ class PlaylistModel(QAbstractTableModel):
Return text for display
"""
log.debug(f"display_role({row=}, {column=}")
# Set / reset column span
column_span = 1
if self.is_header_row(row) and column == HEADER_NOTES_COLUMN:
@ -491,6 +501,8 @@ class PlaylistModel(QAbstractTableModel):
(ie, ignore the first, not-yet-duplicate, track).
"""
log.info("get_duplicate_rows() called")
found = []
result = []
@ -503,6 +515,7 @@ class PlaylistModel(QAbstractTableModel):
else:
found.append(track_id)
log.info(f"get_duplicate_rows() returned: {result=}")
return result
def _get_new_row_number(self, proposed_row_number: Optional[int]) -> int:
@ -513,6 +526,8 @@ class PlaylistModel(QAbstractTableModel):
If not given, return row number to add to end of model.
"""
log.info(f"get_duplicate_rows({proposed_row_number=})")
if proposed_row_number is None or proposed_row_number > len(self.playlist_rows):
# We are adding to the end of the list
new_row_number = len(self.playlist_rows)
@ -522,6 +537,7 @@ class PlaylistModel(QAbstractTableModel):
else:
new_row_number = proposed_row_number
log.info(f"get_new_row_number() return: {new_row_number=}")
return new_row_number
def get_row_info(self, row_number: int) -> PlaylistRowData:
@ -554,7 +570,9 @@ class PlaylistModel(QAbstractTableModel):
Return a list of unplayed row numbers
"""
return [a.plr_rownum for a in self.playlist_rows.values() if not a.played]
result = [a.plr_rownum for a in self.playlist_rows.values() if not a.played]
log.info(f"get_unplayed_rows() returned: {result=}")
return result
def headerData(
self,
@ -713,6 +731,8 @@ class PlaylistModel(QAbstractTableModel):
Insert a row.
"""
log.info(f"insert_row({proposed_row_number=}, {track_id=}, {note=})")
new_row_number = self._get_new_row_number(proposed_row_number)
with Session() as session:
@ -796,6 +816,8 @@ class PlaylistModel(QAbstractTableModel):
Move the playlist rows given to to_row and below.
"""
log.info(f"move_rows({from_rows=}, {to_row_number=}")
# Build a {current_row_number: new_row_number} dictionary
row_map: dict[int, int] = {}
@ -858,6 +880,10 @@ class PlaylistModel(QAbstractTableModel):
Move the playlist rows given to to_row and below of to_playlist.
"""
log.info(
f"move_rows_between_playlists({from_rows=}, {to_row_number=}, {to_playlist_model=}"
)
to_playlist_id = to_playlist_model.playlist_id
# Row removal must be wrapped in beginRemoveRows ..
@ -916,6 +942,8 @@ class PlaylistModel(QAbstractTableModel):
Move existing_prd track to new_row_number and append note to any existing note
"""
log.info(f"move_track_add_note({new_row_number=}, {existing_prd=}, {note=}")
if note:
with Session() as session:
plr = session.get(PlaylistRows, existing_prd.plrid)
@ -937,6 +965,8 @@ class PlaylistModel(QAbstractTableModel):
Add the existing_prd track details to the existing header at header_row_number
"""
log.info(f"move_track_to_header({header_row_number=}, {existing_prd=}, {note=}")
if existing_prd.track_id:
if note and existing_prd.note:
note += "\n" + existing_prd.note
@ -949,6 +979,8 @@ class PlaylistModel(QAbstractTableModel):
and execute any found
"""
log.info(f"obs_scene_change({row_number=})")
# Check any headers before this row
idx = row_number - 1
while self.is_header_row(idx):
@ -985,6 +1017,8 @@ class PlaylistModel(QAbstractTableModel):
- update display
"""
log.info("previous_track_ended()")
# Sanity check
if not track_sequence.previous.track_id:
log.error("playlistmodel:previous_track_ended called with no current track")
@ -1018,6 +1052,8 @@ class PlaylistModel(QAbstractTableModel):
Remove track from row, retaining row as a header row
"""
log.info(f"remove_track({row_number=})")
with Session() as session:
plr = session.get(PlaylistRows, self.playlist_rows[row_number].plrid)
if plr:
@ -1044,6 +1080,8 @@ class PlaylistModel(QAbstractTableModel):
Signal handler for when row ordering has changed
"""
log.info("reset_track_sequence_row_numbers()")
# Check the track_sequence next, now and previous plrs and
# update the row number
with Session() as session:
@ -1074,6 +1112,8 @@ class PlaylistModel(QAbstractTableModel):
return: [[20, 21], [17], [13], [9, 10], [7], [2, 3, 4, 5]]
"""
log.info(f"_reversed_contiguous_row_groups({row_numbers=} called")
result: List[List[int]] = []
temp: List[int] = []
last_value = row_numbers[0] - 1
@ -1088,6 +1128,7 @@ class PlaylistModel(QAbstractTableModel):
result.append(temp)
result.reverse()
log.info(f"_reversed_contiguous_row_groups() returned: {result=}")
return result
def rowCount(self, index: QModelIndex = QModelIndex()) -> int:
@ -1100,6 +1141,8 @@ class PlaylistModel(QAbstractTableModel):
Signal handler for when row ordering has changed
"""
log.info(f"row_order_changed({playlist_id=}) {self.playlist_id=}")
# Only action if this is for us
if playlist_id != self.playlist_id:
return
@ -1134,6 +1177,8 @@ class PlaylistModel(QAbstractTableModel):
Set row_number as next track. If row_number is None, clear next track.
"""
log.info(f"set_next_row({row_number=})")
next_row_was = track_sequence.next.plr_rownum
if row_number is None:
@ -1272,6 +1317,8 @@ class PlaylistModel(QAbstractTableModel):
Update track start/end times in self.playlist_rows
"""
log.info("update_track_times()")
next_start_time: Optional[datetime] = None
update_rows: List[int] = []
@ -1364,6 +1411,9 @@ class PlaylistProxyModel(QSortFilterProxyModel):
# Search all columns
self.setFilterKeyColumn(-1)
def __repr__(self) -> str:
return (f"<PlaylistProxyModel: source_model={self.source_model}>")
def filterAcceptsRow(self, source_row: int, source_parent: QModelIndex) -> bool:
"""
Subclass to filter by played status
@ -1399,7 +1449,8 @@ class PlaylistProxyModel(QSortFilterProxyModel):
if (
previous_plr
and previous_plr.plr_rownum == source_row
and previous_plr.playlist_id == self.source_model.playlist_id
and previous_plr.playlist_id
== self.source_model.playlist_id
):
if track_sequence.now.start_time:
if datetime.now() > (

View File

@ -40,6 +40,7 @@ from helpers import (
show_OK,
show_warning,
)
from log import log
from models import Settings
if TYPE_CHECKING:
@ -119,7 +120,9 @@ class EscapeDelegate(QStyledItemDelegate):
proxy_model = index.model()
edit_index = proxy_model.mapToSource(index)
self.original_text = self.source_model.data(edit_index, Qt.ItemDataRole.EditRole)
self.original_text = self.source_model.data(
edit_index, Qt.ItemDataRole.EditRole
)
editor.setPlainText(self.original_text.value())
def setModelData(self, editor, model, index):
@ -166,6 +169,7 @@ class PlaylistTab(QTableView):
# Save passed settings
self.musicmuster = musicmuster
self.playlist_id = playlist_id
log.info(f"PlaylistTab.__init__({playlist_id=})")
# Set up widget
self.source_model = PlaylistModel(playlist_id)
@ -244,6 +248,7 @@ class PlaylistTab(QTableView):
from_rows = self.selected_model_row_numbers()
to_index = self.indexAt(event.position().toPoint())
to_model_row = self.proxy_model.mapToSource(to_index).row()
log.info(f"PlaylistTab.dropEvent(): {from_rows=}, {to_index=}, {to_model_row=}")
if (
0 <= min(from_rows) <= self.source_model.rowCount()
@ -358,7 +363,8 @@ class PlaylistTab(QTableView):
if track_path == self.musicmuster.audacity_file_path:
# This track was opened in Audacity
self._add_context_menu(
"Update from Audacity", lambda: self._import_from_audacity(model_row_number)
"Update from Audacity",
lambda: self._import_from_audacity(model_row_number),
)
else:
self._add_context_menu(
@ -381,7 +387,8 @@ class PlaylistTab(QTableView):
# Remove track from row
if track_row and not current_row and not next_row:
self._add_context_menu(
"Remove track from row", lambda: proxy_model.remove_track(model_row_number)
"Remove track from row",
lambda: proxy_model.remove_track(model_row_number),
)
# Add track to section header (ie, make this a track row)
@ -456,6 +463,8 @@ class PlaylistTab(QTableView):
Called when column width changes. Save new width to database.
"""
log.info(f"_column_resize({column_number=}, {_old=}, {_new=}")
header = self.horizontalHeader()
if not header:
return
@ -509,6 +518,7 @@ class PlaylistTab(QTableView):
"""
rows_to_delete = self.get_selected_rows()
log.info(f"_delete_rows({rows_to_delete=}")
row_count = len(rows_to_delete)
if row_count < 1:
return
@ -527,17 +537,25 @@ class PlaylistTab(QTableView):
row does not have a track, return empty string.
"""
log.info("get_selected_row_track_path() called")
model_row_number = self.source_model_selected_row_number()
if model_row_number is None:
return ""
return self.source_model.get_row_track_path(model_row_number)
result = ""
else:
result = self.source_model.get_row_track_path(model_row_number)
log.info(f"get_selected_row_track_path() returned: {result=}")
return result
def get_selected_rows(self) -> List[int]:
"""Return a list of model-selected row numbers sorted by row"""
log.info("get_selected_rows() called")
# Use a set to deduplicate result (a selected row will have all
# items in that row selected)
return sorted(
result = sorted(
list(
set(
[
@ -548,6 +566,9 @@ class PlaylistTab(QTableView):
)
)
log.info(f"get_selected_rows() returned: {result=}")
return result
def _import_from_audacity(self, row_number: int) -> None:
"""
Import current Audacity track to passed row
@ -586,7 +607,7 @@ class PlaylistTab(QTableView):
show_OK(self.musicmuster, "Track info", txt)
def _mark_as_unplayed(self, row_numbers: List[int]) -> None:
"""Rescan track"""
"""Mark row as unplayed"""
self.source_model.mark_unplayed(row_numbers)
self.clear_selection()
@ -620,6 +641,8 @@ class PlaylistTab(QTableView):
If playlist_id is us, resize rows
"""
log.info(f"resize_rows({playlist_id=}) {self.playlist_id=}")
if playlist_id != self.playlist_id:
return
@ -664,9 +687,7 @@ class PlaylistTab(QTableView):
selected_index = self._selected_row_index()
if selected_index is None:
return None
if hasattr(self.proxy_model, "mapToSource"):
return self.proxy_model.mapToSource(selected_index).row()
return selected_index.row()
return self.proxy_model.mapToSource(selected_index).row()
def selected_model_row_numbers(self) -> List[int]:
"""
@ -711,6 +732,8 @@ class PlaylistTab(QTableView):
def _set_column_widths(self) -> None:
"""Column widths from settings"""
log.info("_set_column_widths()")
header = self.horizontalHeader()
if not header:
return
@ -731,6 +754,7 @@ class PlaylistTab(QTableView):
"""
model_row_number = self.source_model_selected_row_number()
log.info(f"set_row_as_next_track() {model_row_number=}")
if model_row_number is None:
return
self.source_model.set_next_row(model_row_number)
@ -743,11 +767,18 @@ class PlaylistTab(QTableView):
Implement spanning of cells, initiated by signal
"""
log.debug(
f"_span_cells({playlist_id=}, {row=}, "
f"{column=}, {rowSpan=}, {columnSpan=}) {self.playlist_id=}"
)
if playlist_id != self.playlist_id:
return
proxy_model = self.proxy_model
edit_index = proxy_model.mapFromSource(self.source_model.createIndex(row, column))
edit_index = proxy_model.mapFromSource(
self.source_model.createIndex(row, column)
)
row = edit_index.row()
column = edit_index.column()

22
poetry.lock generated
View File

@ -274,7 +274,7 @@ colorama = {version = "*", markers = "platform_system == \"Windows\""}
name = "colorama"
version = "0.4.6"
description = "Cross-platform colored terminal text."
category = "dev"
category = "main"
optional = false
python-versions = "!=3.0.*,!=3.1.*,!=3.2.*,!=3.3.*,!=3.4.*,!=3.5.*,!=3.6.*,>=2.7"
files = [
@ -282,6 +282,24 @@ files = [
{file = "colorama-0.4.6.tar.gz", hash = "sha256:08695f5cb7ed6e0531a20572697297273c47b8cae5a63ffc6d6ed5c201be6e44"},
]
[[package]]
name = "colorlog"
version = "6.8.0"
description = "Add colours to the output of Python's logging module."
category = "main"
optional = false
python-versions = ">=3.6"
files = [
{file = "colorlog-6.8.0-py3-none-any.whl", hash = "sha256:4ed23b05a1154294ac99f511fabe8c1d6d4364ec1f7fc989c7fb515ccc29d375"},
{file = "colorlog-6.8.0.tar.gz", hash = "sha256:fbb6fdf9d5685f2517f388fb29bb27d54e8654dd31f58bc2a3b217e967a95ca6"},
]
[package.dependencies]
colorama = {version = "*", markers = "sys_platform == \"win32\""}
[package.extras]
development = ["black", "flake8", "mypy", "pytest", "types-colorama"]
[[package]]
name = "decorator"
version = "5.1.1"
@ -2189,4 +2207,4 @@ testing = ["big-O", "jaraco.functools", "jaraco.itertools", "more-itertools", "p
[metadata]
lock-version = "2.0"
python-versions = "^3.9"
content-hash = "5bd0a9ae09f61079a0325639485adb206357cd5ea942944ccb5855f2a83d4db6"
content-hash = "3ba4a6affcb5c77a3c0e4b0f7c12d2b7f5d192a68bf7e71eb6a4e58024b5f4e7"

View File

@ -26,6 +26,7 @@ pyqt6 = "^6.5.0"
pyqt6-webengine = "^6.5.0"
pygame = "^2.4.0"
pyqtgraph = "^0.13.3"
colorlog = "^6.8.0"
[tool.poetry.dev-dependencies]
ipdb = "^0.13.9"