From 2454e8e4b91ac38680a835c7ddc73eea55696f3b Mon Sep 17 00:00:00 2001
From: Keith Edmunds <kae@tiger-computing.co.uk>
Date: Sat, 13 Apr 2024 10:39:51 +0100
Subject: [PATCH] Tidy up logging around issue #223

---
 app/music.py         |  2 +-
 app/musicmuster.py   | 15 ++++++---------
 app/playlistmodel.py | 18 ++++++------------
 3 files changed, 13 insertions(+), 22 deletions(-)

diff --git a/app/music.py b/app/music.py
index 0aecc21..d5a295f 100644
--- a/app/music.py
+++ b/app/music.py
@@ -44,7 +44,7 @@ class FadeTrack(QRunnable):
             sleep(1 / Config.FADEOUT_STEPS_PER_SECOND)
 
         self.player.stop()
-        log.error(f"Releasing player {self.player=}")
+        log.debug(f"Releasing player {self.player=}")
         self.player.release()
 
 
diff --git a/app/musicmuster.py b/app/musicmuster.py
index 019705b..64a0f7d 100755
--- a/app/musicmuster.py
+++ b/app/musicmuster.py
@@ -1146,34 +1146,31 @@ 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")
+        log.debug("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()")
+        log.error("Pause before calling active_proxy_model().current_track_started()")
+        sleep(2)
         self.active_proxy_model().current_track_started()
+        sleep(2)
+        log.error("Pause finished after calling active_proxy_model().current_track_started()")
 
         # Update headers
-        sleep(1)
-        log.error("update headers")
+        log.debug("update headers")
         self.update_headers()
 
     def preview(self) -> None:
diff --git a/app/playlistmodel.py b/app/playlistmodel.py
index 6648202..aea00a2 100644
--- a/app/playlistmodel.py
+++ b/app/playlistmodel.py
@@ -5,7 +5,6 @@ import re
 from datetime import datetime, timedelta
 from enum import auto, Enum
 from operator import attrgetter
-from time import sleep
 from random import shuffle
 from typing import List, Optional
 
@@ -272,21 +271,18 @@ 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")
+        # TODO: log.error used to debug #223 - change to log.debug later
+        log.debug("Call OBS scene change")
         self.obs_scene_change(row_number)
 
         with Session() as session:
             # Update Playdates in database
-            sleep(1)
-            log.error("update playdates")
+            log.debug("update playdates")
             Playdates(session, track_sequence.now.track_id)
 
             # Mark track as played in playlist
-            sleep(1)
-            log.error("Mark track as played")
+            log.debug("Mark track as played")
             plr = session.get(PlaylistRows, track_sequence.now.plr_id)
             if plr:
                 plr.played = True
@@ -295,8 +291,7 @@ 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")
+            log.debug("Update track times")
             if prd:
                 prd.start_time = track_sequence.now.start_time
                 prd.end_time = track_sequence.now.end_time
@@ -313,8 +308,7 @@ class PlaylistModel(QAbstractTableModel):
 
             # Find next track
             # Get all unplayed track rows
-            sleep(1)
-            log.error("Find next track")
+            log.debug("Find next track")
             next_row = None
             unplayed_rows = self.get_unplayed_rows()
             if unplayed_rows: