Fix: Suppress spurious end-file event when starting playback and tts.speak (#179)

* bugfix: supress first end of file event and only callback on second one
* add some notes on testing
* fixed tts.speak
* fix unduck after timer end
* use custom docker-entrypoint on dev container
* change mv to copy in the docs when using .env file

linux_voice_assistant/entity.py

@@ -83,6 +83,7 @@ class MediaPlayerEntity(ESPHomeEntity):
         done_callback: Optional[Callable[[], None]] = None,
     ) -> Iterable[message.Message]:
         if announcement:
+            self._log.debug("PLAY: announcement true")
             if self.music_player.is_playing:
                 # Announce, resume music
                 self.music_player.pause()
@@ -104,6 +105,7 @@ class MediaPlayerEntity(ESPHomeEntity):
                     ),
                 )
         else:
+            self._log.debug("PLAY: announcement false")
             # Music
             self.music_player.play(
                 url,
@@ -124,6 +126,7 @@ class MediaPlayerEntity(ESPHomeEntity):
             self._log.debug("MediaPlayerCommandRequest matched for this key")
 
             if msg.has_media_url:
+                self._log.debug("Executing PLAY")
                 self._log.debug("Message has media URL: %s", msg.media_url)
                 announcement = msg.has_announcement and msg.announcement
                 yield from self.play(msg.media_url, announcement=announcement)
@@ -192,6 +195,8 @@ class MediaPlayerEntity(ESPHomeEntity):
             self._log.warning("Unknown message type received: %s", type(msg))
 
     def _update_state(self, new_state: MediaPlayerState) -> MediaPlayerStateResponse:
+        self._log.debug("SET NEW STATE: %s => %s", self.state, new_state)
+        self._log.debug("SET NEW STATE: %s => %s", self.state.name, new_state.name)
         self.state = new_state
         return self._get_state_message()
 

linux_voice_assistant/mpv_player.py

@@ -105,6 +105,12 @@ class MpvMediaPlayer:
             finally:
                 self._done_callback = None
 
+    @property
+    def is_playing(self) -> bool:
+        """Check if the player is currently playing or paused."""
+        state = self._player.state()
+        return state in (PlayerState.PLAYING, PlayerState.PAUSED, PlayerState.LOADING)
+
     def set_volume(self, volume: float) -> None:
         """
         Set playback volume.

linux_voice_assistant/player/libmpv.py

@@ -1,3 +1,4 @@
+import logging
 import threading
 from typing import Optional, Callable
 
@@ -18,6 +19,7 @@ class LibMpvPlayer(AudioPlayer):
     """
 
     def __init__(self, device: Optional[str] = None) -> None:
+        self._log = logging.getLogger(self.__class__.__name__)
         self._state: PlayerState = PlayerState.IDLE
         self._state_lock = threading.Lock()
 
@@ -37,8 +39,8 @@ class LibMpvPlayer(AudioPlayer):
 
         # Callback Handling
         self._done_callback: Optional[Callable[[], None]] = None
-        self._suppress_end_event = False
         self._mpv.event_callback("end-file")(self._on_end_file)
+        self._mpv.event_callback("start-file")(self._on_start_file)
 
     # -------- Playback control --------
 
@@ -56,10 +58,11 @@ class LibMpvPlayer(AudioPlayer):
             done_callback: Optional callback invoked when playback finishes.
             stop_first: If True, start playback in paused state.
         """
-        self._done_callback = done_callback
-        self._mpv.pause = stop_first
         with self._state_lock:
+            self._log.debug("play: current_state=%s", self._state)
+            self._done_callback = done_callback
             self._set_state(PlayerState.LOADING)
+        self._mpv.pause = stop_first
         self._mpv.play(url)
 
     def pause(self) -> None:
@@ -70,6 +73,7 @@ class LibMpvPlayer(AudioPlayer):
 
     def resume(self) -> None:
         """Resume playback if paused."""
+        self._log.debug("unduck() called")
         with self._state_lock:
             self._mpv.pause = False
             self._set_state(PlayerState.PLAYING)
@@ -78,13 +82,14 @@ class LibMpvPlayer(AudioPlayer):
         """
         Stop playback.
 
-        If called for track replacement, suppresses end-of-playback handling
-        (state transition to IDLE and done callback) to allow seamless
-        playback transitions.
+        If called for track replacement, clears the callback to prevent
+        it from being invoked during the transition.
         """
+        self._log.debug("unduck() called")
         with self._state_lock:
             if for_replacement:
-                self._suppress_end_event = True
+                # Clear callback to prevent invocation during track transition
+                self._done_callback = None
             self._mpv.stop()
 
     def state(self) -> PlayerState:
@@ -101,6 +106,7 @@ class LibMpvPlayer(AudioPlayer):
         Args:
             volume: Volume level (0.0–100.0).
         """
+        self._log.debug("unduck() called")
         with self._state_lock:
             self._user_volume = max(0.0, min(100.0, float(volume)))
             self._apply_volume()
@@ -112,12 +118,14 @@ class LibMpvPlayer(AudioPlayer):
         Args:
             factor: Ducking factor (0.0–1.0).
         """
+        self._log.debug("unduck() called")
         with self._state_lock:
             self._duck_factor = max(0.0, min(1.0, float(factor)))
             self._apply_volume()
 
     def unduck(self) -> None:
         """Restore volume to the user-defined level."""
+        self._log.debug("unduck() called")
         with self._state_lock:
             self._duck_factor = 1.0
             self._apply_volume()
@@ -126,6 +134,7 @@ class LibMpvPlayer(AudioPlayer):
 
     def _apply_volume(self) -> None:
         """Apply effective volume (user volume × duck factor) to mpv."""
+        self._log.debug("unduck() called")
         effective = self._user_volume * self._duck_factor
         self._mpv.volume = max(0.0, min(100.0, effective))
 
@@ -133,8 +142,27 @@ class LibMpvPlayer(AudioPlayer):
         callback: Optional[Callable[[], None]] = None
 
         with self._state_lock:
-            if self._suppress_end_event:
-                self._suppress_end_event = False
+            # mpv events: event.data is a MpvEventEndFile object with a 'reason' attribute
+            # The reason is an integer constant (see mpv.END_FILE_REASON_*)
+            end_file_data = event.data
+            reason = getattr(end_file_data, "reason", -1) if end_file_data else -1
+            
+            # mpv END_FILE_REASON constants:
+            # 0 = eof (end of file), 1 = stop, 2 = abort, 3 = quit, 4 = error
+            is_eof = (reason == 0)
+            
+            self._log.debug(
+                "_on_end_file: reason=%s (is_eof=%s), state=%s, has_callback=%s",
+                reason,
+                is_eof,
+                self._state,
+                self._done_callback is not None,
+            )
+            
+            # Only process "eof" (reason=0) events as actual track completion.
+            # Other reasons are from track changes, stops, or errors.
+            if not is_eof:
+                self._log.debug("_on_end_file: ignoring non-eof event (reason=%s)", reason)
                 return
 
             self._set_state(PlayerState.IDLE)
@@ -142,12 +170,20 @@ class LibMpvPlayer(AudioPlayer):
             self._done_callback = None
 
         if callback is not None:
+            self._log.debug("_on_end_file: invoking callback")
             try:
                 callback()
             except RuntimeError:
                 # Callback errors must never break the player
                 pass
 
+    def _on_start_file(self, event) -> None:
+        """Called when mpv starts playing a file."""
+        self._log.debug("unduck() called")
+        with self._state_lock:
+            self._log.debug("_on_start_file: state=%s", self._state)
+            self._set_state(PlayerState.PLAYING)
+
     def _on_mpv_log(self, level: str, prefix: str, text: str) -> None:
         """
         Handle mpv log messages.

linux_voice_assistant/satellite.py

@@ -275,6 +275,7 @@ class VoiceSatelliteProtocol(APIServer):
                 data[arg.name] = arg.value
 
             self.handle_voice_event(VoiceAssistantEventType(msg.event_type), data)
+        # assist_satellite.announce HERE
         elif isinstance(msg, VoiceAssistantAnnounceRequest):
             _LOGGER.debug("Announcing: %s", msg.text)
 
@@ -410,6 +411,7 @@ class VoiceSatelliteProtocol(APIServer):
         if self._timer_finished:
             # Stop timer instead
             self._timer_finished = False
+            self.unduck()
             self.state.tts_player.stop()
             _LOGGER.debug("Stopping timer finished sound")
             return
@@ -429,12 +431,14 @@ class VoiceSatelliteProtocol(APIServer):
 
     def stop(self) -> None:
         self.state.active_wake_words.discard(self.state.stop_word.id)
-        self.state.tts_player.stop()
 
         if self._timer_finished:
             self._timer_finished = False
+            self.unduck()
+            self.state.tts_player.stop()
             _LOGGER.debug("Stopping timer finished sound")
         else:
+            self.state.tts_player.stop()
             _LOGGER.debug("TTS response stopped manually")
             self._tts_finished()
 
@@ -471,6 +475,7 @@ class VoiceSatelliteProtocol(APIServer):
 
     def _play_timer_finished(self) -> None:
         if not self._timer_finished:
+            _LOGGER.debug("Timer finished sound stopped")
             self.unduck()
             return