Debugging for #223

app/musicmuster.py

@@ -1123,34 +1123,15 @@ class Window(QMainWindow, Ui_MainWindow):
 
         # Restore volume if -3dB active
         if self.btnDrop3db.isChecked():
+            log.debug("Reset -3db button")
             self.btnDrop3db.setChecked(False)
 
-        # Show closing volume graph
-        if track_sequence.now.fade_graph:
-            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
         self.music.play(track_sequence.now.path, position)
 
-        # Note that track is playing
-        track_sequence.now.start()
-        self.playing = True
-
-        # Disable play next controls
-        self.catch_return_key = True
-        self.show_status_message("Play controls: Disabled", 0)
-
-        # Notify model
-        self.active_proxy_model().current_track_started()
-
-        # Update headers
-        self.update_headers()
-
         # Ensure 100% volume
         # For as-yet unknown reasons. sometimes the volume gets
         # reset to zero within 200mS or so of starting play. This
@@ -1165,6 +1146,36 @@ class Window(QMainWindow, Ui_MainWindow):
                     break
             sleep(0.1)
 
+        # TODO: remove sleep() calls - used to try to isolate bug #223
+        # Show closing volume graph
+        sleep(1)
+        if track_sequence.now.fade_graph:
+            track_sequence.now.fade_graph.plot()
+        else:
+            log.error("No fade_graph")
+
+        # Note that track is playing
+        sleep(1)
+        log.error("set track_sequence")
+        track_sequence.now.start()
+        self.playing = True
+
+        # Disable play next controls
+        sleep(1)
+        log.error("catch return key")
+        self.catch_return_key = True
+        self.show_status_message("Play controls: Disabled", 0)
+
+        # Notify model
+        sleep(1)
+        log.error("active_proxy_model().current_track_started()")
+        self.active_proxy_model().current_track_started()
+
+        # Update headers
+        sleep(1)
+        log.error("update headers")
+        self.update_headers()
+
     def preview(self) -> None:
         """
         Preview selected or next track. We use a different mechanism to

app/playlistmodel.py

@@ -2,11 +2,10 @@
 from __future__ import annotations
 import obsws_python as obs  # type: ignore
 import re
-from dataclasses import dataclass
 from datetime import datetime, timedelta
 from enum import auto, Enum
 from operator import attrgetter
-from pprint import pprint
+from time import sleep
 from random import shuffle
 from typing import List, Optional
 
@@ -273,14 +272,21 @@ class PlaylistModel(QAbstractTableModel):
             )
             return
 
+        # TODO: remove sleep/log calls, used to debug #223
         # Check for OBS scene change
+        sleep(1)
+        log.error("Call OBS scene change")
         self.obs_scene_change(row_number)
 
         with Session() as session:
             # Update Playdates in database
+            sleep(1)
+            log.error("update playdates")
             Playdates(session, track_sequence.now.track_id)
 
             # Mark track as played in playlist
+            sleep(1)
+            log.error("Mark track as played")
             plr = session.get(PlaylistRows, track_sequence.now.plr_id)
             if plr:
                 plr.played = True
@@ -289,6 +295,8 @@ class PlaylistModel(QAbstractTableModel):
                 log.error(f"Can't retrieve plr, {track_sequence.now.plr_id=}")
 
             # Update track times
+            sleep(1)
+            log.error("Update track times")
             if prd:
                 prd.start_time = track_sequence.now.start_time
                 prd.end_time = track_sequence.now.end_time
@@ -305,6 +313,8 @@ class PlaylistModel(QAbstractTableModel):
 
             # Find next track
             # Get all unplayed track rows
+            sleep(1)
+            log.error("Find next track")
             next_row = None
             unplayed_rows = self.get_unplayed_rows()
             if unplayed_rows: