Improve function logging

Use @log_call decorator

Add 'checked' parameter to menu slots because PyQt6 will pass a
boolean 'checked' parameter even when the menu item can't be checked.

Remove superfluous logging calls.

app/file_importer.py

@@ -104,9 +104,7 @@ class FileImporter:
     # variable or an instance variable are effectively the same thing.
     workers: dict[str, DoTrackImport] = {}
 
-    def __init__(
+    def __init__(self, base_model: PlaylistModel, row_number: int) -> None:
-        self, base_model: PlaylistModel, row_number: int = None
-    ) -> None:
         """
         Initialise the FileImporter singleton instance.
         """

app/log.py

@@ -80,9 +80,22 @@ log = logging.getLogger(Config.LOG_NAME)
 
 
 def handle_exception(exc_type, exc_value, exc_traceback):
-    error = str(exc_value)
+    """
+    Inform user of exception
+    """
+
+    # Navigate to the inner stack frame
+    tb = exc_traceback
+    while tb.tb_next:
+        tb = tb.tb_next
+
+    fname = os.path.basename(tb.tb_frame.f_code.co_filename)
+    lineno = tb.tb_lineno
+    msg = f"ApplicationError: {exc_value}\nat {fname}:{lineno}"
+    logmsg = f"ApplicationError: {exc_value} at {fname}:{lineno}"
+
     if issubclass(exc_type, ApplicationError):
-        log.error(error)
+        log.error(logmsg)
     else:
         # Handle unexpected errors (log and display)
         error_msg = "".join(traceback.format_exception(exc_type, exc_value, exc_traceback))
@@ -105,7 +118,6 @@ def handle_exception(exc_type, exc_value, exc_traceback):
             )
     if QApplication.instance() is not None:
         fname = os.path.split(exc_traceback.tb_frame.f_code.co_filename)[1]
-        msg = f"ApplicationError: {error}\nat {fname}:{exc_traceback.tb_lineno}"
         QMessageBox.critical(None, "Application Error", msg)
 
 
@@ -124,13 +136,13 @@ def log_call(func):
         args_repr = [truncate_large(a) for a in args]
         kwargs_repr = [f"{k}={truncate_large(v)}" for k, v in kwargs.items()]
         params_repr = ", ".join(args_repr + kwargs_repr)
-        log.debug(f"call {func.__name__}({params_repr})")
+        log.debug(f"call {func.__name__}({params_repr})", stacklevel=2)
         try:
             result = func(*args, **kwargs)
-            log.debug(f"return {func.__name__}: {truncate_large(result)}")
+            log.debug(f"return {func.__name__}: {truncate_large(result)}", stacklevel=2)
             return result
         except Exception as e:
-            log.debug(f"exception in {func.__name__}: {e}")
+            log.debug(f"exception in {func.__name__}: {e}", stacklevel=2)
             raise
     return wrapper
 

app/musicmuster.py

@@ -478,6 +478,7 @@ class ManageQueries(ItemlistManager):
 
         self.populate_table(query_list)
 
+    @log_call
     def delete_item(self, query_id: int) -> None:
         """delete query"""
 
@@ -490,7 +491,6 @@ class ManageQueries(ItemlistManager):
             "Delete query",
             f"Delete query '{query.name}': " "Are you sure?",
         ):
-            log.debug(f"manage_queries: delete {query=}")
             self.session.delete(query)
             self.session.commit()
 
@@ -583,6 +583,7 @@ class ManageTemplates(ItemlistManager):
 
         self.populate_table(template_list)
 
+    @log_call
     def delete_item(self, template_id: int) -> None:
         """delete template"""
 
@@ -606,7 +607,6 @@ class ManageTemplates(ItemlistManager):
                 else:
                     self.musicmuster.playlist_section.tabPlaylist.removeTab(open_idx)
 
-            log.debug(f"manage_templates: delete {template=}")
             self.session.delete(template)
             self.session.commit()
 
@@ -1234,7 +1234,6 @@ class Window(QMainWindow):
                 for playlist_id, idx in open_playlist_ids.items():
                     playlist = session.get(Playlists, playlist_id)
                     if playlist:
-                        log.debug(f"Set {playlist=} tab to {idx=}")
                         playlist.tab = idx
 
                 # Save window attributes
@@ -1455,6 +1454,7 @@ class Window(QMainWindow):
 
     # # # # # # # # # # Playlist management functions # # # # # # # # # #
 
+    @log_call
     def _create_playlist(
         self, session: Session, name: str, template_id: int
     ) -> Playlists:
@@ -1463,8 +1463,6 @@ class Window(QMainWindow):
         if template_id > 0, and return the Playlists object.
         """
 
-        log.debug(f" _create_playlist({name=}, {template_id=})")
-
         return Playlists(session, name, template_id)
 
     @log_call
@@ -1478,8 +1476,6 @@ class Window(QMainWindow):
          return: tab index
         """
 
-        log.debug(f" _open_playlist({playlist=}, {is_template=})")
-
         # Create base model and proxy model
         base_model = PlaylistModel(playlist.id, is_template)
         proxy_model = PlaylistProxyModel()
@@ -1498,6 +1494,7 @@ class Window(QMainWindow):
 
         return idx
 
+    @log_call
     def create_playlist_from_template(self, session: Session, template_id: int) -> None:
         """
         Prompt for new playlist name and create from passed template_id
@@ -1519,7 +1516,8 @@ class Window(QMainWindow):
         self._open_playlist(playlist)
         session.commit()
 
-    def delete_playlist(self) -> None:
+    @log_call
+    def delete_playlist(self, checked: bool = False) -> None:
         """
         Delete current playlist
         """
@@ -1538,7 +1536,7 @@ class Window(QMainWindow):
             else:
                 log.error("Failed to retrieve playlist")
 
-    def open_existing_playlist(self) -> None:
+    def open_existing_playlist(self, checked: bool = False) -> None:
         """Open existing playlist"""
 
         with db.Session() as session:
@@ -1550,7 +1548,7 @@ class Window(QMainWindow):
                 self._open_playlist(playlist)
                 session.commit()
 
-    def save_as_template(self) -> None:
+    def save_as_template(self, checked: bool = False) -> None:
         """Save current playlist as template"""
 
         with db.Session() as session:
@@ -1626,7 +1624,7 @@ class Window(QMainWindow):
 
     # # # # # # # # # # Manage templates and queries # # # # # # # # # #
 
-    def manage_queries_wrapper(self):
+    def manage_queries_wrapper(self, checked: bool = False) -> None:
         """
         Simply instantiate the manage_queries class
         """
@@ -1634,7 +1632,7 @@ class Window(QMainWindow):
         with db.Session() as session:
             _ = ManageQueries(session, self)
 
-    def manage_templates_wrapper(self):
+    def manage_templates_wrapper(self, checked: bool = False) -> None:
         """
         Simply instantiate the manage_queries class
         """
@@ -1644,12 +1642,12 @@ class Window(QMainWindow):
 
     # # # # # # # # # # Miscellaneous functions # # # # # # # # # #
 
-    def select_duplicate_rows(self) -> None:
+    def select_duplicate_rows(self, checked: bool = False) -> None:
         """Call playlist to select duplicate rows"""
 
         self.active_tab().select_duplicate_rows()
 
-    def about(self) -> None:
+    def about(self, checked: bool = False) -> None:
         """Get git tag and database name"""
 
         try:
@@ -1678,7 +1676,7 @@ class Window(QMainWindow):
         track_sequence.set_next(None)
         self.update_headers()
 
-    def clear_selection(self) -> None:
+    def clear_selection(self, checked: bool = False) -> None:
         """Clear row selection"""
 
         # Unselect any selected rows
@@ -1688,7 +1686,7 @@ class Window(QMainWindow):
         # Clear the search bar
         self.search_playlist_clear()
 
-    def close_playlist_tab(self) -> bool:
+    def close_playlist_tab(self, checked: bool = False) -> bool:
         """
         Close active playlist tab, called by menu item
         """
@@ -1774,6 +1772,7 @@ class Window(QMainWindow):
         self.signals.search_songfacts_signal.connect(self.open_songfacts_browser)
         self.signals.search_wikipedia_signal.connect(self.open_wikipedia_browser)
 
+    @log_call
     def current_row_or_end(self) -> int:
         """
         If a row or rows are selected, return the row number of the first
@@ -1785,14 +1784,14 @@ class Window(QMainWindow):
             return self.current.selected_rows[0]
         return self.current.base_model.rowCount()
 
-    def debug(self):
+    def debug(self, checked: bool = False) -> None:
         """Invoke debugger"""
 
         import ipdb  # type: ignore
 
         ipdb.set_trace()
 
-    def download_played_tracks(self) -> None:
+    def download_played_tracks(self, checked: bool = False) -> None:
         """Download a CSV of played tracks"""
 
         dlg = DownloadCSV(self)
@@ -1823,6 +1822,7 @@ class Window(QMainWindow):
         if track_sequence.current:
             track_sequence.current.drop3db(self.footer_section.btnDrop3db.isChecked())
 
+    @log_call
     def enable_escape(self, enabled: bool) -> None:
         """
         Manage signal to enable/disable handling ESC character.
@@ -1831,11 +1831,10 @@ class Window(QMainWindow):
         so we need to disable it here while editing.
         """
 
-        log.debug(f"enable_escape({enabled=})")
-
         if "clear_selection" in self.menu_actions:
             self.menu_actions["clear_selection"].setEnabled(enabled)
 
+    @log_call
     def end_of_track_actions(self) -> None:
         """
 
@@ -1875,7 +1874,7 @@ class Window(QMainWindow):
         # if not self.stop_autoplay:
         #     self.play_next()
 
-    def export_playlist_tab(self) -> None:
+    def export_playlist_tab(self, checked: bool = False) -> None:
         """Export the current playlist to an m3u file"""
 
         playlist_id = self.current.playlist_id
@@ -1916,7 +1915,7 @@ class Window(QMainWindow):
                         "\n"
                     )
 
-    def fade(self) -> None:
+    def fade(self, checked: bool = False) -> None:
         """Fade currently playing track"""
 
         if track_sequence.current:
@@ -1952,7 +1951,7 @@ class Window(QMainWindow):
         # Reset row heights
         self.active_tab().resize_rows()
 
-    def import_files_wrapper(self) -> None:
+    def import_files_wrapper(self, checked: bool = False) -> None:
         """
         Pass import files call to file_importer module
         """
@@ -1962,7 +1961,7 @@ class Window(QMainWindow):
         self.importer = FileImporter(self.current.base_model, self.current_row_or_end())
         self.importer.start()
 
-    def insert_header(self) -> None:
+    def insert_header(self, checked: bool = False) -> None:
         """Show dialog box to enter header text and add to playlist"""
 
         # Get header text
@@ -1977,7 +1976,7 @@ class Window(QMainWindow):
                 note=dlg.textValue(),
             )
 
-    def insert_track(self) -> None:
+    def insert_track(self, checked: bool = False) -> None:
         """Show dialog box to select and add track from database"""
 
         with db.Session() as session:
@@ -1998,7 +1997,6 @@ class Window(QMainWindow):
         with db.Session() as session:
             for playlist in Playlists.get_open(session):
                 if playlist:
-                    log.debug(f"load_last_playlists() loaded {playlist=}")
                     # Create tab
                     playlist_ids.append(self._open_playlist(playlist))
 
@@ -2014,7 +2012,7 @@ class Window(QMainWindow):
             Playlists.clear_tabs(session, playlist_ids)
             session.commit()
 
-    def lookup_row_in_songfacts(self) -> None:
+    def lookup_row_in_songfacts(self, checked: bool = False) -> None:
         """
         Display songfacts page for title in highlighted row
         """
@@ -2025,7 +2023,7 @@ class Window(QMainWindow):
 
         self.signals.search_songfacts_signal.emit(track_info.title)
 
-    def lookup_row_in_wikipedia(self) -> None:
+    def lookup_row_in_wikipedia(self, checked: bool = False) -> None:
         """
         Display Wikipedia page for title in highlighted row or next track
         """
@@ -2036,7 +2034,7 @@ class Window(QMainWindow):
 
         self.signals.search_wikipedia_signal.emit(track_info.title)
 
-    def mark_rows_for_moving(self) -> None:
+    def mark_rows_for_moving(self, checked: bool = False) -> None:
         """
         Cut rows ready for pasting.
         """
@@ -2050,6 +2048,7 @@ class Window(QMainWindow):
             f"mark_rows_for_moving(): {self.move_source_rows=} {self.move_source_model=}"
         )
 
+    @log_call
     def move_playlist_rows(self, row_numbers: list[int]) -> None:
         """
         Move passed playlist rows to another playlist
@@ -2094,7 +2093,7 @@ class Window(QMainWindow):
                 if ts:
                     ts.update_playlist_and_row(session)
 
-    def move_selected(self) -> None:
+    def move_selected(self, checked: bool = False) -> None:
         """
         Move selected rows to another playlist
         """
@@ -2105,7 +2104,7 @@ class Window(QMainWindow):
 
         self.move_playlist_rows(selected_rows)
 
-    def move_unplayed(self) -> None:
+    def move_unplayed(self, checked: bool = False) -> None:
         """
         Move unplayed rows to another playlist
         """
@@ -2137,7 +2136,8 @@ class Window(QMainWindow):
 
         webbrowser.get("browser").open_new_tab(url)
 
-    def paste_rows(self, dummy_for_profiling: int | None = None) -> None:
+    @log_call
+    def paste_rows(self, checked: bool = False) -> None:
         """
         Paste earlier cut rows.
         """
@@ -2170,7 +2170,8 @@ class Window(QMainWindow):
         if set_next_row:
             to_playlist_model.set_next_row(set_next_row)
 
-    def play_next(self, position: Optional[float] = None) -> None:
+    @log_call
+    def play_next(self, position: Optional[float] = None, checked: bool = False) -> None:
         """
         Play next track, optionally from passed position.
 
@@ -2366,7 +2367,7 @@ class Window(QMainWindow):
         if ok:
             log.debug("quicklog: " + dlg.textValue())
 
-    def rename_playlist(self) -> None:
+    def rename_playlist(self, checked: bool = False) -> None:
         """
         Rename current playlist
         """
@@ -2422,7 +2423,7 @@ class Window(QMainWindow):
 
         return False
 
-    def resume(self) -> None:
+    def resume(self, checked: bool = False) -> None:
         """
         Resume playing last track. We may be playing the next track
         or none; take care of both eventualities.
@@ -2463,7 +2464,7 @@ class Window(QMainWindow):
             )
             track_sequence.current.start_time -= dt.timedelta(milliseconds=elapsed_ms)
 
-    def search_playlist(self) -> None:
+    def search_playlist(self, checked: bool = False) -> None:
         """Show text box to search playlist"""
 
         # Disable play controls so that 'return' in search box doesn't
@@ -2521,7 +2522,8 @@ class Window(QMainWindow):
             height = Settings.get_setting(session, "mainwindow_height").f_int or 100
             self.setGeometry(x, y, width, height)
 
-    def set_selected_track_next(self) -> None:
+    @log_call
+    def set_selected_track_next(self, checked: bool = False) -> None:
         """
         Set currently-selected row on visible playlist tab as next track
         """
@@ -2532,6 +2534,7 @@ class Window(QMainWindow):
         else:
             log.error("No active tab")
 
+    @log_call
     def set_tab_colour(self, widget: PlaylistTab, colour: QColor) -> None:
         """
         Find the tab containing the widget and set the text colour
@@ -2593,7 +2596,8 @@ class Window(QMainWindow):
 
         self.active_tab().scroll_to_top(playlist_track.row_number)
 
-    def stop(self) -> None:
+    @log_call
+    def stop(self, checked: bool = False) -> None:
         """Stop playing immediately"""
 
         self.stop_autoplay = True

app/playlistmodel.py

@@ -78,8 +78,6 @@ class PlaylistModel(QAbstractTableModel):
     ) -> None:
         super().__init__()
 
-        log.debug("PlaylistModel.__init__()")
-
         self.playlist_id = playlist_id
         self.is_template = is_template
 
@@ -138,6 +136,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return header_row
 
+    @log_call
     def add_track_to_header(
         self, row_number: int, track_id: int, note: Optional[str] = None
     ) -> None:
@@ -145,8 +144,6 @@ class PlaylistModel(QAbstractTableModel):
         Add track to existing header row
         """
 
-        log.debug(f"{self}: add_track_to_header({row_number=}, {track_id=}, {note=}")
-
         # Get existing row
         try:
             rat = self.playlist_rows[row_number]
@@ -238,6 +235,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return QBrush()
 
+    @log_call
     def begin_reset_model(self, playlist_id: int) -> None:
         """
         Reset model if playlist_id is ours
@@ -252,6 +250,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return len(Col)
 
+    @log_call
     def current_track_started(self) -> None:
         """
         Notification from musicmuster that the current track has just
@@ -267,8 +266,6 @@ class PlaylistModel(QAbstractTableModel):
         - update track times
         """
 
-        log.debug(f"{self}: current_track_started()")
-
         if not track_sequence.current:
             return
 
@@ -375,6 +372,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return QVariant()
 
+    @log_call
     def delete_rows(self, row_numbers: list[int]) -> None:
         """
         Delete passed rows from model
@@ -389,7 +387,6 @@ class PlaylistModel(QAbstractTableModel):
 
         with db.Session() as session:
             for row_number in sorted(row_numbers, reverse=True):
-                log.debug(f"{self}: delete_rows(), {row_number=}")
                 super().beginRemoveRows(QModelIndex(), row_number, row_number)
                 # We need to remove data from the underlying data store,
                 # which is the database, but we cache in
@@ -464,15 +461,13 @@ class PlaylistModel(QAbstractTableModel):
 
         return ""
 
+    @log_call
     def end_reset_model(self, playlist_id: int) -> None:
         """
         End model reset if this is our playlist
         """
 
-        log.debug(f"{self}: end_reset_model({playlist_id=})")
-
         if playlist_id != self.playlist_id:
-            log.debug(f"{self}: end_reset_model: not us ({self.playlist_id=})")
             return
         with db.Session() as session:
             self.refresh_data(session)
@@ -551,14 +546,13 @@ class PlaylistModel(QAbstractTableModel):
 
         return boldfont
 
+    @log_call
     def get_duplicate_rows(self) -> list[int]:
         """
         Return a list of duplicate rows. If track appears in rows 2, 3 and 4, return [3, 4]
         (ie, ignore the first, not-yet-duplicate, track).
         """
 
-        log.debug(f"{self}: get_duplicate_rows() called")
-
         found = []
         result = []
 
@@ -571,9 +565,9 @@ class PlaylistModel(QAbstractTableModel):
             else:
                 found.append(track_id)
 
-        log.debug(f"{self}: get_duplicate_rows() returned: {result=}")
         return result
 
+    @log_call
     def _get_new_row_number(self, proposed_row_number: Optional[int]) -> int:
         """
         Sanitises proposed new row number.
@@ -582,8 +576,6 @@ class PlaylistModel(QAbstractTableModel):
         If not given, return row number to add to end of model.
         """
 
-        log.debug(f"{self}: _get_new_row_number({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)
@@ -593,7 +585,6 @@ class PlaylistModel(QAbstractTableModel):
         else:
             new_row_number = proposed_row_number
 
-        log.debug(f"{self}: get_new_row_number() return: {new_row_number=}")
         return new_row_number
 
     def get_row_info(self, row_number: int) -> RowAndTrack:
@@ -603,6 +594,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return self.playlist_rows[row_number]
 
+    @log_call
     def get_row_track_id(self, row_number: int) -> Optional[int]:
         """
         Return id of track associated with row or None if no track associated
@@ -719,6 +711,7 @@ class PlaylistModel(QAbstractTableModel):
                 ]
                 self.invalidate_row(row_number, roles)
 
+    @log_call
     def insert_row(
         self,
         proposed_row_number: Optional[int],
@@ -729,8 +722,6 @@ class PlaylistModel(QAbstractTableModel):
         Insert a row.
         """
 
-        log.debug(f"{self}: insert_row({proposed_row_number=}, {track_id=}, {note=})")
-
         new_row_number = self._get_new_row_number(proposed_row_number)
 
         with db.Session() as session:
@@ -758,26 +749,24 @@ class PlaylistModel(QAbstractTableModel):
         ]
         self.invalidate_rows(list(range(new_row_number, len(self.playlist_rows))), roles)
 
+    @log_call
     def invalidate_row(self, modified_row: int, roles: list[Qt.ItemDataRole]) -> None:
         """
         Signal to view to refresh invalidated row
         """
 
-        log.debug(f"issue285: {self}: invalidate_row({modified_row=})")
-
         self.dataChanged.emit(
             self.index(modified_row, 0),
             self.index(modified_row, self.columnCount() - 1),
             roles
         )
 
+    @log_call
     def invalidate_rows(self, modified_rows: list[int], roles: list[Qt.ItemDataRole]) -> None:
         """
         Signal to view to refresh invlidated rows
         """
 
-        log.debug(f"issue285: {self}: invalidate_rows({modified_rows=})")
-
         for modified_row in modified_rows:
             # only invalidate required roles
             self.invalidate_row(modified_row, roles)
@@ -791,6 +780,7 @@ class PlaylistModel(QAbstractTableModel):
             return self.playlist_rows[row_number].path == ""
         return False
 
+    @log_call
     def is_played_row(self, row_number: int) -> bool:
         """
         Return True if row is an unplayed track row, else False
@@ -798,6 +788,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return self.playlist_rows[row_number].played
 
+    @log_call
     def is_track_in_playlist(self, track_id: int) -> Optional[RowAndTrack]:
         """
         If this track_id is in the playlist, return the RowAndTrack object
@@ -838,6 +829,7 @@ class PlaylistModel(QAbstractTableModel):
         # Copy to self.playlist_rows
         self.playlist_rows = new_playlist_rows
 
+    @log_call
     def mark_unplayed(self, row_numbers: list[int]) -> None:
         """
         Mark row as unplayed
@@ -861,13 +853,12 @@ class PlaylistModel(QAbstractTableModel):
         ]
         self.invalidate_rows(row_numbers, roles)
 
+    @log_call
     def move_rows(self, from_rows: list[int], to_row_number: int) -> None:
         """
         Move the playlist rows given to to_row and below.
         """
 
-        log.debug(f"{self}: move_rows({from_rows=}, {to_row_number=}")
-
         # Build a {current_row_number: new_row_number} dictionary
         row_map: dict[int, int] = {}
 
@@ -930,6 +921,7 @@ class PlaylistModel(QAbstractTableModel):
         ]
         self.invalidate_rows(list(row_map.keys()), roles)
 
+    @log_call
     def move_rows_between_playlists(
         self,
         from_rows: list[int],
@@ -940,11 +932,6 @@ class PlaylistModel(QAbstractTableModel):
         Move the playlist rows given to to_row and below of to_playlist.
         """
 
-        log.debug(
-            f"{self}: move_rows_between_playlists({from_rows=}, "
-            f"{to_row_number=}, {to_playlist_id=}"
-        )
-
         # Row removal must be wrapped in beginRemoveRows ..
         # endRemoveRows and the row range must be contiguous. Process
         # the highest rows first so the lower row numbers are unchanged
@@ -997,6 +984,7 @@ class PlaylistModel(QAbstractTableModel):
         self.signals.end_reset_model_signal.emit(to_playlist_id)
         self.update_track_times()
 
+    @log_call
     def move_track_add_note(
         self, new_row_number: int, existing_rat: RowAndTrack, note: str
     ) -> None:
@@ -1004,10 +992,6 @@ class PlaylistModel(QAbstractTableModel):
         Move existing_rat track to new_row_number and append note to any existing note
         """
 
-        log.debug(
-            f"{self}: move_track_add_note({new_row_number=}, {existing_rat=}, {note=}"
-        )
-
         if note:
             with db.Session() as session:
                 playlist_row = session.get(PlaylistRows, existing_rat.playlistrow_id)
@@ -1024,6 +1008,7 @@ class PlaylistModel(QAbstractTableModel):
         self.move_rows([existing_rat.row_number], new_row_number)
         self.signals.resize_rows_signal.emit(self.playlist_id)
 
+    @log_call
     def move_track_to_header(
         self,
         header_row_number: int,
@@ -1034,24 +1019,19 @@ class PlaylistModel(QAbstractTableModel):
         Add the existing_rat track details to the existing header at header_row_number
         """
 
-        log.debug(
-            f"{self}: move_track_to_header({header_row_number=}, {existing_rat=}, {note=}"
-        )
-
         if existing_rat.track_id:
             if note and existing_rat.note:
                 note += "\n" + existing_rat.note
             self.add_track_to_header(header_row_number, existing_rat.track_id, note)
             self.delete_rows([existing_rat.row_number])
 
+    @log_call
     def obs_scene_change(self, row_number: int) -> None:
         """
         Check this row and any preceding headers for OBS scene change command
         and execute any found
         """
 
-        log.debug(f"{self}: obs_scene_change({row_number=})")
-
         # Check any headers before this row
         idx = row_number - 1
         while self.is_header_row(idx):
@@ -1080,6 +1060,7 @@ class PlaylistModel(QAbstractTableModel):
                         log.warning(f"{self}: OBS connection refused")
                         return
 
+    @log_call
     def previous_track_ended(self) -> None:
         """
         Notification from musicmuster that the previous track has ended.
@@ -1089,8 +1070,6 @@ class PlaylistModel(QAbstractTableModel):
         - update display
         """
 
-        log.debug(f"{self}: previous_track_ended()")
-
         # Sanity check
         if not track_sequence.previous:
             log.error(
@@ -1111,6 +1090,7 @@ class PlaylistModel(QAbstractTableModel):
         ]
         self.invalidate_row(track_sequence.previous.row_number, roles)
 
+    @log_call
     def refresh_data(self, session: Session) -> None:
         """
         Populate self.playlist_rows with playlist data
@@ -1147,13 +1127,12 @@ class PlaylistModel(QAbstractTableModel):
         p = PlaylistRows.deep_row(session, self.playlist_id, row_number)
         self.playlist_rows[row_number] = RowAndTrack(p)
 
+    @log_call
     def remove_track(self, row_number: int) -> None:
         """
         Remove track from row, retaining row as a header row
         """
 
-        log.debug(f"{self}: remove_track({row_number=})")
-
         with db.Session() as session:
             playlist_row = session.get(
                 PlaylistRows, self.playlist_rows[row_number].playlistrow_id
@@ -1189,6 +1168,7 @@ class PlaylistModel(QAbstractTableModel):
                 self.signals.resize_rows_signal.emit(self.playlist_id)
                 session.commit()
 
+    @log_call
     def reset_track_sequence_row_numbers(self) -> None:
         """
         Signal handler for when row ordering has changed.
@@ -1199,8 +1179,6 @@ class PlaylistModel(QAbstractTableModel):
         looking up the playlistrow_id and retrieving the row number from the database.
         """
 
-        log.debug(f"issue285: {self}: reset_track_sequence_row_numbers()")
-
         # Check the track_sequence.next, current and previous plrs and
         # update the row number
         with db.Session() as session:
@@ -1253,6 +1231,7 @@ class PlaylistModel(QAbstractTableModel):
         ]
         self.invalidate_rows(row_numbers, roles)
 
+    @log_call
     def _reversed_contiguous_row_groups(
         self, row_numbers: list[int]
     ) -> list[list[int]]:
@@ -1265,8 +1244,6 @@ class PlaylistModel(QAbstractTableModel):
             return: [[20, 21], [17], [13], [9, 10], [7], [2, 3, 4, 5]]
         """
 
-        log.debug(f"{self}: _reversed_contiguous_row_groups({row_numbers=} called")
-
         result: list[list[int]] = []
         temp: list[int] = []
         last_value = row_numbers[0] - 1
@@ -1281,12 +1258,11 @@ class PlaylistModel(QAbstractTableModel):
             result.append(temp)
         result.reverse()
 
-        log.debug(f"{self}: _reversed_contiguous_row_groups() returned: {result=}")
         return result
 
     def remove_section_timer_markers(self, header_text: str) -> str:
         """
-        Remove characters used to mark section timeings from
+        Remove characters used to mark section timings from
         passed header text.
 
         Remove text using to signal header colours if colour entry
@@ -1419,6 +1395,7 @@ class PlaylistModel(QAbstractTableModel):
 
         return True
 
+    @log_call
     def set_next_row(self, row_number: Optional[int]) -> None:
         """
         Set row_number as next track. If row_number is None, clear next track.
@@ -1426,8 +1403,6 @@ class PlaylistModel(QAbstractTableModel):
         Return True if successful else False.
         """
 
-        log.debug(f"{self}: set_next_row({row_number=})")
-
         if row_number is None:
             # Clear next track
             if track_sequence.next is not None:
@@ -1636,6 +1611,7 @@ class PlaylistModel(QAbstractTableModel):
                 ]
             )
 
+    @log_call
     def update_or_insert(self, track_id: int, row_number: int) -> None:
         """
         If the passed track_id exists in this playlist, update the
@@ -1660,13 +1636,12 @@ class PlaylistModel(QAbstractTableModel):
         else:
             self.insert_row(proposed_row_number=row_number, track_id=track_id)
 
+    @log_call
     def update_track_times(self) -> None:
         """
         Update track start/end times in self.playlist_rows
         """
 
-        log.debug(f"issue285: {self}: update_track_times()")
-
         next_start_time: Optional[dt.datetime] = None
         update_rows: list[int] = []
         row_count = len(self.playlist_rows)

app/playlists.py

@@ -358,7 +358,8 @@ class PlaylistTab(QTableView):
         # Deselect edited line
         self.clear_selection()
 
-    def dropEvent(self, event: Optional[QDropEvent], dummy: int | None = None) -> None:
+    @log_call
+    def dropEvent(self, event: Optional[QDropEvent]) -> None:
         """
         Move dropped rows
         """
@@ -394,9 +395,6 @@ class PlaylistTab(QTableView):
             destination_index = to_index
 
         to_model_row = self.model().mapToSource(destination_index).row()
-        log.debug(
-            f"PlaylistTab.dropEvent(): {from_rows=}, {destination_index=}, {to_model_row=}"
-        )
 
         # Sanity check
         base_model_row_count = self.get_base_model().rowCount()
@@ -676,8 +674,6 @@ class PlaylistTab(QTableView):
         Called when column width changes. Save new width to database.
         """
 
-        log.debug(f"_column_resize({column_number=}, {_old=}, {_new=}")
-
         header = self.horizontalHeader()
         if not header:
             return
@@ -722,6 +718,7 @@ class PlaylistTab(QTableView):
             cb.clear(mode=cb.Mode.Clipboard)
             cb.setText(track_path, mode=cb.Mode.Clipboard)
 
+    @log_call
     def current_track_started(self) -> None:
         """
         Called when track starts playing
@@ -809,6 +806,7 @@ class PlaylistTab(QTableView):
             else:
                 return TrackInfo(track_id, selected_row)
 
+    @log_call
     def get_selected_row(self) -> Optional[int]:
         """
         Return selected row number. If no rows or multiple rows selected, return None
@@ -820,6 +818,7 @@ class PlaylistTab(QTableView):
         else:
             return None
 
+    @log_call
     def get_selected_rows(self) -> list[int]:
         """Return a list of model-selected row numbers sorted by row"""
 
@@ -832,6 +831,7 @@ class PlaylistTab(QTableView):
 
         return sorted(list(set([self.model().mapToSource(a).row() for a in selected_indexes])))
 
+    @log_call
     def get_top_visible_row(self) -> int:
         """
         Get the viewport of the table view
@@ -954,8 +954,6 @@ class PlaylistTab(QTableView):
         If playlist_id is us, resize rows
         """
 
-        log.debug(f"resize_rows({playlist_id=}) {self.playlist_id=}")
-
         if playlist_id and playlist_id != self.playlist_id:
             return
 
@@ -1002,6 +1000,7 @@ class PlaylistTab(QTableView):
         # Reset selection mode
         self.setSelectionMode(QAbstractItemView.SelectionMode.ExtendedSelection)
 
+    @log_call
     def source_model_selected_row_number(self) -> Optional[int]:
         """
         Return the model row number corresponding to the selected row or None
@@ -1012,6 +1011,7 @@ class PlaylistTab(QTableView):
             return None
         return self.model().mapToSource(selected_index).row()
 
+    @log_call
     def selected_model_row_numbers(self) -> list[int]:
         """
         Return a list of model row numbers corresponding to the selected rows or
@@ -1054,8 +1054,6 @@ class PlaylistTab(QTableView):
     def _set_column_widths(self) -> None:
         """Column widths from settings"""
 
-        log.debug("_set_column_widths()")
-
         header = self.horizontalHeader()
         if not header:
             return