Add log_call decorator and issue 287 logging

app/file_importer.py

@@ -105,15 +105,15 @@ class FileImporter:
     workers: dict[str, DoTrackImport] = {}
 
     def __init__(
-        self, base_model: PlaylistModel, row_number: Optional[int] = None
+        self, base_model: PlaylistModel, row_number: int = None
     ) -> None:
         """
         Initialise the FileImporter singleton instance.
         """
 
+        log.debug(f"FileImporter.__init__({base_model=}, {row_number=})")
+
         # Create ModelData
-        if not row_number:
-            row_number = base_model.rowCount()
         self.model_data = ThreadData(base_model=base_model, row_number=row_number)
 
         # Data structure to track files to import

app/log.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python3
 # Standard library imports
 from collections import defaultdict
+from functools import wraps
 import logging
 import logging.config
 import logging.handlers
@@ -108,4 +109,30 @@ def handle_exception(exc_type, exc_value, exc_traceback):
         QMessageBox.critical(None, "Application Error", msg)
 
 
+def truncate_large(obj, limit=5):
+    """Helper to truncate large lists or other iterables."""
+    if isinstance(obj, (list, tuple, set)):
+        if len(obj) > limit:
+            return f"{type(obj).__name__}(len={len(obj)}, items={list(obj)[:limit]}...)"
+
+    return repr(obj)
+
+
+def log_call(func):
+    @wraps(func)
+    def wrapper(*args, **kwargs):
+        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})")
+        try:
+            result = func(*args, **kwargs)
+            log.debug(f"return {func.__name__}: {truncate_large(result)}")
+            return result
+        except Exception as e:
+            log.debug(f"exception in {func.__name__}: {e}")
+            raise
+    return wrapper
+
+
 sys.excepthook = handle_exception

app/musicmuster.py

@@ -73,7 +73,7 @@ from config import Config
 from dialogs import TrackSelectDialog
 from file_importer import FileImporter
 from helpers import ask_yes_no, file_is_unreadable, get_name
-from log import log
+from log import log, log_call
 from models import db, Playdates, PlaylistRows, Playlists, Queries, Settings, Tracks
 from music_manager import RowAndTrack, track_sequence
 from playlistmodel import PlaylistModel, PlaylistProxyModel
@@ -1467,6 +1467,7 @@ class Window(QMainWindow):
 
         return Playlists(session, name, template_id)
 
+    @log_call
     def _open_playlist(self, playlist: Playlists, is_template: bool = False) -> int:
         """
         With passed playlist:
@@ -1989,6 +1990,7 @@ class Window(QMainWindow):
             dlg.exec()
             session.commit()
 
+    @log_call
     def load_last_playlists(self) -> None:
         """Load the playlists that were open when the last session closed"""
 
@@ -2725,6 +2727,7 @@ class Window(QMainWindow):
                 self.catch_return_key = False
                 self.show_status_message("Play controls: Enabled", 0)
                 # Re-enable 10ms timer (see above)
+                log.debug(f"issue287: {self.timer10.isActive()=}")
                 if not self.timer10.isActive():
                     self.timer10.start(10)
                     log.debug("issue223: update_clocks: 10ms timer enabled")

app/playlistmodel.py

@@ -46,7 +46,7 @@ from helpers import (
     remove_substring_case_insensitive,
     set_track_metadata,
 )
-from log import log
+from log import log, log_call
 from models import db, NoteColours, Playdates, PlaylistRows, Tracks
 from music_manager import RowAndTrack, track_sequence
 

app/playlists.py

@@ -44,7 +44,7 @@ from helpers import (
     show_OK,
     show_warning,
 )
-from log import log
+from log import log, log_call
 from models import db, Settings
 from music_manager import track_sequence
 from playlistmodel import PlaylistModel, PlaylistProxyModel