Skip to content

fix(spotify_connect): reload provider on broken pipe errors#2997

Draft
prydie wants to merge 1 commit intomusic-assistant:devfrom
prydie:fix/spotify-connect-broken-pipe
Draft

fix(spotify_connect): reload provider on broken pipe errors#2997
prydie wants to merge 1 commit intomusic-assistant:devfrom
prydie:fix/spotify-connect-broken-pipe

Conversation

@prydie
Copy link
Contributor

@prydie prydie commented Jan 19, 2026

Description

This PR fixes a "Zombie Process" issue where the librespot binary remains running but non-functional after a Broken Pipe (os error 32) event.

The Fix:
I have extended the stderr processor to trap this specific fatal error. When detected, the provider now triggers a self-reload via self.mass.load_provider_config(self.config).

Motivation and Context

  • The Problem: librespot handles output pipe errors by pausing rather than crashing ("Sticky Sink"). Music Assistant sees the process as healthy (PID exists), but the named pipe to FFmpeg is permanently broken.
  • Why Reload? Standard restart logic failed because librespot handles SIGTERM gracefully and exits with Code 0. Music Assistant interprets Exit 0 as a user-initiated stop and does not restart the provider.
  • The Solution: Triggering load_provider_config forces a complete unload/load cycle, ensuring the broken pipe and zombie process are cleaned up and a fresh session is established.

Steps to Reproduce

  1. Start playback on a Spotify Connect player.
  2. On the host machine (outside the container), identify the ffmpeg process ID:
    docker top music_assistant | grep ffmpeg
  3. Kill the process ID (PID) found in the previous step to force the pipe break:
    kill <PID>
  4. Observe logs and player state.

Verification

1. Original Failure Mode (Zombie State)
The error occurs, the player pauses, and remains unavailable indefinitely. The process does not exit.

2026-01-19 20:59:12.802 ERROR [librespot_core::session] Broken pipe (os error 32)
2026-01-19 20:59:13.843 DEBUG Spotify Connect paused, releasing player UI state...

# ... Process remains active (PID exists) but audio is permanently broken ...

2. With Fix (Provider reload)
The error is detected immediately, the provider reloads, and the player becomes available again.

2026-01-19 22:24:00.424 DEBUG [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T22:24:00Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 22:24:00.424 ERROR (MainThread) [music_assistant.spotify_connect] Librespot output pipe is broken (Zombie State). Restarting process...
# ... Provider unloads and restarts, user is able to restart playback ...
2026-01-19 22:24:01.470 DEBUG (MainThread) [music_assistant.spotify_connect] Authenticated to Spotify as: prydie
2026-01-19 22:24:15.286 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie

Note: Playback stops when the pipe breaks. Once the provider reloads (approx. 15s), the user must manually re-select the device/press play to resume, but a container restart is no longer required.

Type of change

  • Bug fix (non-breaking change which fixes an issue)

The librespot binary enters a "Zombie" state on broken pipe errors,
staying alive unable to play audio.

This patch updates the existing stderr processor to detect the
"Broken pipe" error and trigger a full provider reload. This forces
a complete teardown and fresh start of the provider instance.
@OzGav OzGav added the bugfix label Jan 19, 2026
@prydie
Copy link
Contributor Author

prydie commented Jan 19, 2026

Raw failure mode logs:

2026-01-19 19:08:53.483 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:53Z INFO  librespot_connect::spirc] session update: <Ok(SESSION_DELETED)> for self, current session_id eac11d1d14f7c0815a1769266c72300a, new session_id eac11d1d14f7c0815a1769266c72300a
2026-01-19 19:08:53.906 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:53Z INFO  librespot_connect::spirc] device became inactive
2026-01-19 19:08:54.091 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:54Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:08:54.123 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:54Z WARN  librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
2026-01-19 19:08:56.528 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:56Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:08:56.561 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:56Z INFO  librespot_playback::player] Loading <California> with Spotify URI <spotify:track:46BuJdwxV43a6qLrICP27l>
2026-01-19 19:08:56.637 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:56Z INFO  librespot_connect::spirc] session update: <Ok(NEW_SESSION)> for self, current session_id eac11d1d14f7c0815a1769266c72300a, new session_id b54565fc604f442e4289a8378dd7ed97
2026-01-19 19:08:56.783 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:56Z WARN  librespot_playback::player] Invalid start position of 4592795 ms exceeds track's duration of 222186 ms, starting track from the beginning
2026-01-19 19:08:56.952 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:56Z INFO  librespot_playback::player] <California> (222186 ms) loaded
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:57Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Autoplay
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:08:57Z ERROR librespot_connect::context_resolver] setup of state failed: Invalid state { context is not available. type: Autoplay }, last used resolve ResolveContext {
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] resolve: Uri(
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] "spotify:playlist:37i9dQZF1E39PkbAiIxkz3",
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] ),
2026-01-19 19:08:57.246 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] fallback: Some(
2026-01-19 19:08:57.247 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] "spotify:track:46BuJdwxV43a6qLrICP27l",
2026-01-19 19:08:57.247 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] ),
2026-01-19 19:08:57.247 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] update: Default,
2026-01-19 19:08:57.247 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] action: Replace,
2026-01-19 19:08:57.247 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] }
2026-01-19 19:09:00.132 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:08:59.814359', 'event': 'session_disconnected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:09:00.145 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session disconnected
2026-01-19 19:09:00.145 DEBUG (MainThread) [music_assistant.spotify_connect] Playback ended on player 1c:db:d4:77:cc:ec, clearing active player
2026-01-19 19:09:00.610 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:00.551231', 'event': 'session_connected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:09:00.610 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie, current username: None
2026-01-19 19:09:00.610 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session connected for user: prydie
2026-01-19 19:09:00.610 DEBUG (MainThread) [music_assistant.spotify_connect] Found matching Spotify music provider - enabling playback control via Web API
2026-01-19 19:09:00.801 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:00.739551', 'event': 'session_client_changed', 'client_id': '65b708073fc0480ea92a077233ca87bd', 'client_name': '', 'client_brand_name': '', 'client_model_name': ''}
2026-01-19 19:09:00.990 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:00.926772', 'event': 'volume_changed', 'volume': '50175'}
2026-01-19 19:09:00.990 DEBUG (MainThread) [music_assistant.spotify_connect] Ignoring initial volume_changed event (0.38s after session_connect)
2026-01-19 19:09:01.169 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.110714', 'event': 'auto_play_changed', 'auto_play': 'true'}
2026-01-19 19:09:01.342 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.283593', 'event': 'filter_explicit_content_changed', 'filter': 'false'}
2026-01-19 19:09:01.519 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.459296', 'event': 'shuffle_changed', 'shuffle': 'false'}
2026-01-19 19:09:01.697 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.637097', 'event': 'repeat_changed', 'repeat': 'false'}
2026-01-19 19:09:01.817 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.754674', 'event': 'sink'}
2026-01-19 19:09:01.818 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:09:02.058 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:09:02.062 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:01.823691', 'event': 'play_request_id_changed'}
2026-01-19 19:09:02.769 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:02.192841', 'event': 'loading', 'track_id': '46BuJdwxV43a6qLrICP27l'}
2026-01-19 19:09:03.106 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:02.960893', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '46BuJdwxV43a6qLrICP27l', 'uri': 'spotify:track:46BuJdwxV43a6qLrICP27l', 'name': 'California', 'duration_ms': '222186', 'is_explicit': 'false', 'language': ['en'], 'covers': ['https://i.scdn.co/image/ab67616d0000b273b4d3b2740b535c9b56210df1', 'https://i.scdn.co/image/ab67616d00001e02b4d3b2740b535c9b56210df1', 'https://i.scdn.co/image/ab67616d00004851b4d3b2740b535c9b56210df1']}, 'track_metadata_fields': {'number': '5', 'disc_number': '1', 'popularity': '58', 'album': 'Sons Of The East', 'artists': ['Sons Of The East'], 'album_artists': ['Sons Of The East']}}
2026-01-19 19:09:03.325 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:03.255480', 'event': 'paused', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '0'}
2026-01-19 19:09:03.325 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for 1c:db:d4:77:cc:ec
2026-01-19 19:09:03.521 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:03.462741', 'event': 'playing', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '0'}
2026-01-19 19:09:03.522 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:09:03.524 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:09:05.411 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:05.470 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:07.512 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:07.453672', 'event': 'position_correction', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '0'}
2026-01-19 19:09:08.807 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:08Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 19:09:08.960 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:08.902428', 'event': 'sink'}
2026-01-19 19:09:08.960 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:09:08.972 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:09:09.137 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:09.080060', 'event': 'paused', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '3284'}
2026-01-19 19:09:09.137 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for 1c:db:d4:77:cc:ec
2026-01-19 19:09:09.161 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:11.858 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:11.799122', 'event': 'sink'}
2026-01-19 19:09:11.859 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:09:11.861 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:09:11.865 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:11.799122', 'event': 'playing', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '3284'}
2026-01-19 19:09:11.977 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:13.170 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:13Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 19:09:13.321 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:13.264111', 'event': 'sink'}
2026-01-19 19:09:13.322 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:09:13.325 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:09:13.502 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:13.441100', 'event': 'paused', 'track_id': '46BuJdwxV43a6qLrICP27l', 'position_ms': '6153'}
2026-01-19 19:09:13.502 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for 1c:db:d4:77:cc:ec
2026-01-19 19:09:14.071 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:22.810 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:22Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:09:22.933 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:22Z INFO  librespot_playback::player] Loading <Change It All> with Spotify URI <spotify:track:7lWKpA4JZrGVqYURuz7cnu>
2026-01-19 19:09:22.940 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:22Z INFO  librespot_connect::spirc] device became inactive
2026-01-19 19:09:22.975 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:22.914246', 'event': 'session_connected', 'user_name': 'prydie', 'connection_id': 'ZGQ4YTRhYzEtMWM5YS00Yzk0LTlkNTYtYmMxNjI1NWYwOWY3K2RlYWxlcit0Y3A6Ly8wYWNhNDEyMC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQkE3NzY0NjExNUM5NDNFNjFENTI5MzdGNUM0QTdDQjkyOUVERTc0Q0FBQUUzQTMyRUEzQUVCQjI5OEJEOTk1Ng=='}
2026-01-19 19:09:22.975 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie, current username: prydie
2026-01-19 19:09:22.981 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:22Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:09:23.011 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:23Z WARN  librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
2026-01-19 19:09:23.164 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.091589', 'event': 'session_client_changed', 'client_id': '65b708073fc0480ea92a077233ca87bd', 'client_name': '', 'client_brand_name': '', 'client_model_name': ''}
2026-01-19 19:09:23.170 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:23.111456', 'event': 'session_disconnected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:09:23.170 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session disconnected
2026-01-19 19:09:23.170 DEBUG (MainThread) [music_assistant.spotify_connect] Playback ended on player 1c:db:d4:77:cc:ec, clearing active player
2026-01-19 19:09:23.285 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:23Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Autoplay
2026-01-19 19:09:23.286 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:23Z ERROR librespot_connect::context_resolver] setup of state failed: Invalid state { context is not available. type: Autoplay }, last used resolve ResolveContext {
2026-01-19 19:09:23.286 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] resolve: Uri(
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] "spotify:playlist:37i9dQZF1E39PkbAiIxkz3",
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] ),
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] fallback: Some(
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] "spotify:track:7lWKpA4JZrGVqYURuz7cnu",
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] ),
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] update: Default,
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] action: Replace,
2026-01-19 19:09:23.287 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] }
2026-01-19 19:09:23.352 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.290983', 'event': 'volume_changed', 'volume': '13107'}
2026-01-19 19:09:23.352 DEBUG (MainThread) [music_assistant.spotify_connect] Ignoring initial volume_changed event (0.38s after session_connect)
2026-01-19 19:09:23.362 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:23.304139', 'event': 'stopped', 'track_id': '46BuJdwxV43a6qLrICP27l'}
2026-01-19 19:09:23.514 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:23Z INFO  librespot_playback::player] <Change It All> (247413 ms) loaded
2026-01-19 19:09:23.521 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.463522', 'event': 'auto_play_changed', 'auto_play': 'true'}
2026-01-19 19:09:23.685 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.627418', 'event': 'filter_explicit_content_changed', 'filter': 'false'}
2026-01-19 19:09:23.849 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.791621', 'event': 'shuffle_changed', 'shuffle': 'false'}
2026-01-19 19:09:24.014 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:23.955352', 'event': 'repeat_changed', 'repeat': 'false'}
2026-01-19 19:09:24.187 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.127646', 'event': 'play_request_id_changed'}
2026-01-19 19:09:24.354 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.296998', 'event': 'loading', 'track_id': '7lWKpA4JZrGVqYURuz7cnu'}
2026-01-19 19:09:24.382 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.320715', 'event': 'sink'}
2026-01-19 19:09:24.382 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:09:24.385 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:09:24.527 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.469165', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '7lWKpA4JZrGVqYURuz7cnu', 'uri': 'spotify:track:7lWKpA4JZrGVqYURuz7cnu', 'name': 'Change It All', 'duration_ms': '247413', 'is_explicit': 'false', 'language': ['en'], 'covers': ['https://i.scdn.co/image/ab67616d0000b273152ccb666ca2998e85dd2d8e', 'https://i.scdn.co/image/ab67616d00001e02152ccb666ca2998e85dd2d8e', 'https://i.scdn.co/image/ab67616d00004851152ccb666ca2998e85dd2d8e']}, 'track_metadata_fields': {'number': '1', 'disc_number': '1', 'popularity': '52', 'album': 'Change It All', 'artists': ['Harrison Storm'], 'album_artists': ['Harrison Storm']}}
2026-01-19 19:09:24.692 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.634328', 'event': 'paused', 'track_id': '7lWKpA4JZrGVqYURuz7cnu', 'position_ms': '6148'}
2026-01-19 19:09:24.692 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for e0:8c:fe:6b:22:44
2026-01-19 19:09:24.859 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:24.802276', 'event': 'playing', 'track_id': '7lWKpA4JZrGVqYURuz7cnu', 'position_ms': '6148'}
2026-01-19 19:09:24.860 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:09:24.861 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:09:26.093 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:26Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 19:09:26.238 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:26.181330', 'event': 'sink'}
2026-01-19 19:09:26.239 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:09:26.241 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:09:26.405 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:26.346978', 'event': 'paused', 'track_id': '7lWKpA4JZrGVqYURuz7cnu', 'position_ms': '9003'}
2026-01-19 19:09:26.405 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for e0:8c:fe:6b:22:44
2026-01-19 19:09:28.418 DEBUG (MainThread) [music_assistant.spotify_connect] Found Spotify Connect device ID: fc531dc45de7cc545aab6f923fdd48c616bbcb39
2026-01-19 19:09:28.419 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:30.418 DEBUG (MainThread) [music_assistant.spotify_connect] Found Spotify Connect device ID: fc531dc45de7cc545aab6f923fdd48c616bbcb39
2026-01-19 19:09:30.418 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:32.498 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:09:37.880 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:37Z INFO  librespot_connect::spirc] device became inactive
2026-01-19 19:09:37.925 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:37Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:09:37.963 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:09:37Z WARN  librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
2026-01-19 19:09:38.114 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:38.055099', 'event': 'session_disconnected', 'user_name': 'prydie', 'connection_id': 'ZGQ4YTRhYzEtMWM5YS00Yzk0LTlkNTYtYmMxNjI1NWYwOWY3K2RlYWxlcit0Y3A6Ly8wYWNhNDEyMC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQkE3NzY0NjExNUM5NDNFNjFENTI5MzdGNUM0QTdDQjkyOUVERTc0Q0FBQUUzQTMyRUEzQUVCQjI5OEJEOTk1Ng=='}
2026-01-19 19:09:38.114 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session disconnected
2026-01-19 19:09:38.114 DEBUG (MainThread) [music_assistant.spotify_connect] Playback ended on player e0:8c:fe:6b:22:44, clearing active player
2026-01-19 19:09:38.291 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:09:38.233226', 'event': 'stopped', 'track_id': '7lWKpA4JZrGVqYURuz7cnu'}
2026-01-19 19:09:51.163 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:51Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:09:51.188 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:51Z INFO  librespot_playback::player] Loading <Oats In The Water> with Spotify URI <spotify:track:4dr5sJ1p6mdNpK3fIUz8vR>
2026-01-19 19:09:51.314 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:51.255612', 'event': 'session_connected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:09:51.314 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie, current username: None
2026-01-19 19:09:51.314 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session connected for user: prydie
2026-01-19 19:09:51.314 DEBUG (MainThread) [music_assistant.spotify_connect] Found matching Spotify music provider - enabling playback control via Web API
2026-01-19 19:09:51.430 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:51Z INFO  librespot_playback::player] <Oats In The Water> (299381 ms) loaded
2026-01-19 19:09:51.490 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:51.432359', 'event': 'session_client_changed', 'client_id': '65b708073fc0480ea92a077233ca87bd', 'client_name': '', 'client_brand_name': '', 'client_model_name': ''}
2026-01-19 19:09:51.664 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:51.603183', 'event': 'volume_changed', 'volume': '50175'}
2026-01-19 19:09:51.664 DEBUG (MainThread) [music_assistant.spotify_connect] Ignoring initial volume_changed event (0.35s after session_connect)
2026-01-19 19:09:51.722 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:51Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Autoplay
2026-01-19 19:09:51.722 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:09:51Z ERROR librespot_connect::context_resolver] setup of state failed: Invalid state { context is not available. type: Autoplay }, last used resolve ResolveContext {
2026-01-19 19:09:51.722 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] resolve: Uri(
2026-01-19 19:09:51.722 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] "spotify:playlist:37i9dQZF1E39PkbAiIxkz3",
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] ),
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] fallback: Some(
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] "spotify:track:4dr5sJ1p6mdNpK3fIUz8vR",
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] ),
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] update: Default,
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] action: Replace,
2026-01-19 19:09:51.723 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] }
2026-01-19 19:09:51.839 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:51.776426', 'event': 'auto_play_changed', 'auto_play': 'true'}
2026-01-19 19:09:52.015 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:51.954680', 'event': 'filter_explicit_content_changed', 'filter': 'false'}
2026-01-19 19:09:52.184 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.125818', 'event': 'shuffle_changed', 'shuffle': 'false'}
2026-01-19 19:09:52.354 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.296425', 'event': 'repeat_changed', 'repeat': 'false'}
2026-01-19 19:09:52.526 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.468359', 'event': 'play_request_id_changed'}
2026-01-19 19:09:52.699 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.640664', 'event': 'loading', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR'}
2026-01-19 19:09:52.871 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.811363', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR', 'uri': 'spotify:track:4dr5sJ1p6mdNpK3fIUz8vR', 'name': 'Oats In The Water', 'duration_ms': '299381', 'is_explicit': 'false', 'language': ['en'], 'covers': ['https://i.scdn.co/image/ab67616d0000b2732ceca64986ded2c002381060', 'https://i.scdn.co/image/ab67616d00001e022ceca64986ded2c002381060', 'https://i.scdn.co/image/ab67616d000048512ceca64986ded2c002381060']}, 'track_metadata_fields': {'number': '2', 'disc_number': '1', 'popularity': '64', 'album': 'The Burgh Island EP', 'artists': ['Ben Howard'], 'album_artists': ['Ben Howard']}}
2026-01-19 19:09:53.045 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:09:52.987919', 'event': 'paused', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR', 'position_ms': '0'}
2026-01-19 19:10:51.669 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:51Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:10:51.697 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:51Z INFO  librespot_playback::player] Loading <Oats In The Water> with Spotify URI <spotify:track:4dr5sJ1p6mdNpK3fIUz8vR>
2026-01-19 19:10:51.704 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:10:51Z INFO  librespot_connect::spirc] device became inactive
2026-01-19 19:10:51.759 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:10:51Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:10:51.785 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:10:51Z WARN  librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
2026-01-19 19:10:52.012 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:52Z INFO  librespot_playback::player] <Oats In The Water> (299381 ms) loaded
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:52Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Autoplay
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:52Z ERROR librespot_connect::context_resolver] setup of state failed: Invalid state { context is not available. type: Autoplay }, last used resolve ResolveContext {
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] resolve: Uri(
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] "spotify:playlist:37i9dQZF1E39PkbAiIxkz3",
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] ),
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] fallback: Some(
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] "spotify:track:4dr5sJ1p6mdNpK3fIUz8vR",
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] ),
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] update: Default,
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] action: Replace,
2026-01-19 19:10:52.300 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] }
2026-01-19 19:10:52.718 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:10:52.493284', 'event': 'session_disconnected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:10:52.718 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session disconnected
2026-01-19 19:10:52.719 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:52.493440', 'event': 'session_connected', 'user_name': 'prydie', 'connection_id': 'ZGQ4YTRhYzEtMWM5YS00Yzk0LTlkNTYtYmMxNjI1NWYwOWY3K2RlYWxlcit0Y3A6Ly8wYWNhNDEyMC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQkE3NzY0NjExNUM5NDNFNjFENTI5MzdGNUM0QTdDQjkyOUVERTc0Q0FBQUUzQTMyRUEzQUVCQjI5OEJEOTk1Ng=='}
2026-01-19 19:10:52.719 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie, current username: None
2026-01-19 19:10:52.719 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session connected for user: prydie
2026-01-19 19:10:52.719 DEBUG (MainThread) [music_assistant.spotify_connect] Found matching Spotify music provider - enabling playback control via Web API
2026-01-19 19:10:52.890 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:10:52.831667', 'event': 'stopped', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR'}
2026-01-19 19:10:52.891 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:52.832963', 'event': 'session_client_changed', 'client_id': '65b708073fc0480ea92a077233ca87bd', 'client_name': '', 'client_brand_name': '', 'client_model_name': ''}
2026-01-19 19:10:53.061 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.003355', 'event': 'volume_changed', 'volume': '13107'}
2026-01-19 19:10:53.061 DEBUG (MainThread) [music_assistant.spotify_connect] Ignoring initial volume_changed event (0.34s after session_connect)
2026-01-19 19:10:53.230 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.172792', 'event': 'auto_play_changed', 'auto_play': 'true'}
2026-01-19 19:10:53.399 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.342393', 'event': 'filter_explicit_content_changed', 'filter': 'false'}
2026-01-19 19:10:53.564 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.507170', 'event': 'shuffle_changed', 'shuffle': 'false'}
2026-01-19 19:10:53.735 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.674990', 'event': 'repeat_changed', 'repeat': 'false'}
2026-01-19 19:10:53.912 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:53.851213', 'event': 'play_request_id_changed'}
2026-01-19 19:10:54.080 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:54.023070', 'event': 'loading', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR'}
2026-01-19 19:10:54.259 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:54.197368', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR', 'uri': 'spotify:track:4dr5sJ1p6mdNpK3fIUz8vR', 'name': 'Oats In The Water', 'duration_ms': '299381', 'is_explicit': 'false', 'language': ['en'], 'covers': ['https://i.scdn.co/image/ab67616d0000b2732ceca64986ded2c002381060', 'https://i.scdn.co/image/ab67616d00001e022ceca64986ded2c002381060', 'https://i.scdn.co/image/ab67616d000048512ceca64986ded2c002381060']}, 'track_metadata_fields': {'number': '2', 'disc_number': '1', 'popularity': '64', 'album': 'The Burgh Island EP', 'artists': ['Ben Howard'], 'album_artists': ['Ben Howard']}}
2026-01-19 19:10:54.431 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:54.371626', 'event': 'paused', 'track_id': '4dr5sJ1p6mdNpK3fIUz8vR', 'position_ms': '0'}
2026-01-19 19:10:55.717 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:55Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:10:55.717 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:55Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:10:55.778 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:55Z INFO  librespot_playback::player] Loading <snowfall> with Spotify URI <spotify:track:4xF4ZBGPZKxECeDFrqSAG4>
2026-01-19 19:10:55.904 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:55.843195', 'event': 'play_request_id_changed'}
2026-01-19 19:10:56.000 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:56Z INFO  librespot_playback::player] <snowfall> (124065 ms) loaded
2026-01-19 19:10:56.084 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:56.021502', 'event': 'loading', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4'}
2026-01-19 19:10:56.153 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:56.095192', 'event': 'sink'}
2026-01-19 19:10:56.153 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:10:56.156 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:10:56.270 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:56.206753', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'uri': 'spotify:track:4xF4ZBGPZKxECeDFrqSAG4', 'name': 'snowfall', 'duration_ms': '124065', 'is_explicit': 'false', 'language': ['zxx'], 'covers': ['https://i.scdn.co/image/ab67616d0000b273ed50c8fe9503fd8d73d82f9f', 'https://i.scdn.co/image/ab67616d00001e02ed50c8fe9503fd8d73d82f9f', 'https://i.scdn.co/image/ab67616d00004851ed50c8fe9503fd8d73d82f9f']}, 'track_metadata_fields': {'number': '1', 'disc_number': '1', 'popularity': '84', 'album': 'snowfall', 'artists': ['Øneheart', 'reidenshi'], 'album_artists': ['Øneheart', 'reidenshi']}}
2026-01-19 19:10:56.283 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:10:56.444 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:56.386502', 'event': 'playing', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '0'}
2026-01-19 19:10:57.468 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:10:57Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 19:10:57.614 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:57.556122', 'event': 'sink'}
2026-01-19 19:10:57.614 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:10:57.616 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:10:57.781 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:57.723265', 'event': 'paused', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '2845'}
2026-01-19 19:10:57.781 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for e0:8c:fe:6b:22:44
2026-01-19 19:10:58.241 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:10:59.844 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:59.785865', 'event': 'playing', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '2845'}
2026-01-19 19:10:59.844 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:10:59.845 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:10:59.895 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:10:59.785875', 'event': 'sink'}
2026-01-19 19:11:00.235 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:11:01.167 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:11:01Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)
2026-01-19 19:11:01.321 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:11:01.261546', 'event': 'sink'}
2026-01-19 19:11:01.321 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--wYSNBGF3] on player e0:8c:fe:6b:22:44
2026-01-19 19:11:01.323 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: e0:8c:fe:6b:22:44
2026-01-19 19:11:01.511 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:11:01.443819', 'event': 'paused', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '5701'}
2026-01-19 19:11:01.511 DEBUG (MainThread) [music_assistant.spotify_connect] Spotify Connect paused, releasing player UI state for e0:8c:fe:6b:22:44
2026-01-19 19:11:02.240 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:13:52.820 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:13:52Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:13:52.874 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:13:52Z INFO  librespot_playback::player] Loading <snowfall> with Spotify URI <spotify:track:4xF4ZBGPZKxECeDFrqSAG4>
2026-01-19 19:13:52.891 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:13:52Z INFO  librespot_connect::spirc] device became inactive
2026-01-19 19:13:52.934 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:13:52Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
2026-01-19 19:13:52.975 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect (Holly)] [2026-01-19T19:13:52Z WARN  librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
2026-01-19 19:13:52.988 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:52.927626', 'event': 'session_connected', 'user_name': 'prydie', 'connection_id': 'NDI4NzNmNmQtMTYxZS00N2Q4LTliN2YtNzdjMDIxMmMzZjczK2RlYWxlcit0Y3A6Ly8wYWNhNDBiYS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMEMyNUU1MEFDODMzNTA0MkRDREM3NjYwMjQzRjdEMkRCQTcxQzBENzlDMDA2NkU5M0RCQ0Q0NUFEOTA5NTk1Qw=='}
2026-01-19 19:13:52.988 DEBUG (MainThread) [music_assistant.spotify_connect] Session connected event - username from event: prydie, current username: None
2026-01-19 19:13:52.988 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session connected for user: prydie
2026-01-19 19:13:52.988 DEBUG (MainThread) [music_assistant.spotify_connect] Found matching Spotify music provider - enabling playback control via Web API
2026-01-19 19:13:53.144 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:13:53.083082', 'event': 'session_disconnected', 'user_name': 'prydie', 'connection_id': 'ZGQ4YTRhYzEtMWM5YS00Yzk0LTlkNTYtYmMxNjI1NWYwOWY3K2RlYWxlcit0Y3A6Ly8wYWNhNDEyMC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQkE3NzY0NjExNUM5NDNFNjFENTI5MzdGNUM0QTdDQjkyOUVERTc0Q0FBQUUzQTMyRUEzQUVCQjI5OEJEOTk1Ng=='}
2026-01-19 19:13:53.144 INFO (MainThread) [music_assistant.spotify_connect] Spotify Connect session disconnected
2026-01-19 19:13:53.144 DEBUG (MainThread) [music_assistant.spotify_connect] Playback ended on player e0:8c:fe:6b:22:44, clearing active player
2026-01-19 19:13:53.169 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:13:53Z INFO  librespot_playback::player] <snowfall> (124065 ms) loaded
2026-01-19 19:13:53.174 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:53.113013', 'event': 'session_client_changed', 'client_id': '65b708073fc0480ea92a077233ca87bd', 'client_name': '', 'client_brand_name': '', 'client_model_name': ''}
2026-01-19 19:13:53.329 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect (Holly)]:
{'event_time': '2026-01-19 19:13:53.269597', 'event': 'stopped', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4'}
2026-01-19 19:13:53.363 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:53.302401', 'event': 'volume_changed', 'volume': '50175'}
2026-01-19 19:13:53.363 DEBUG (MainThread) [music_assistant.spotify_connect] Ignoring initial volume_changed event (0.38s after session_connect)
2026-01-19 19:13:53.541 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:53.481781', 'event': 'auto_play_changed', 'auto_play': 'true'}
2026-01-19 19:13:53.715 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:53.657188', 'event': 'filter_explicit_content_changed', 'filter': 'false'}
2026-01-19 19:13:53.906 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:53.843609', 'event': 'shuffle_changed', 'shuffle': 'false'}
2026-01-19 19:13:54.090 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:54.031076', 'event': 'repeat_changed', 'repeat': 'false'}
2026-01-19 19:13:54.279 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:54.214550', 'event': 'play_request_id_changed'}
2026-01-19 19:13:54.463 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:54.403945', 'event': 'loading', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4'}
2026-01-19 19:13:54.636 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:54.578772', 'event': 'track_changed', 'common_metadata_fields': {'item_type': 'Track', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'uri': 'spotify:track:4xF4ZBGPZKxECeDFrqSAG4', 'name': 'snowfall', 'duration_ms': '124065', 'is_explicit': 'false', 'language': ['zxx'], 'covers': ['https://i.scdn.co/image/ab67616d0000b273ed50c8fe9503fd8d73d82f9f', 'https://i.scdn.co/image/ab67616d00001e02ed50c8fe9503fd8d73d82f9f', 'https://i.scdn.co/image/ab67616d00004851ed50c8fe9503fd8d73d82f9f']}, 'track_metadata_fields': {'number': '1', 'disc_number': '1', 'popularity': '84', 'album': 'snowfall', 'artists': ['Øneheart', 'reidenshi'], 'album_artists': ['Øneheart', 'reidenshi']}}
2026-01-19 19:13:54.805 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:54.748092', 'event': 'paused', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '5678'}
2026-01-19 19:13:58.989 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:58.931493', 'event': 'sink'}
2026-01-19 19:13:58.989 INFO (MainThread) [music_assistant.spotify_connect] Starting Spotify Connect playback [spotify_connect--pZhtGRPN] on player 1c:db:d4:77:cc:ec
2026-01-19 19:13:58.992 DEBUG (MainThread) [music_assistant.spotify_connect] Active player set to: 1c:db:d4:77:cc:ec
2026-01-19 19:13:58.998 DEBUG (MainThread) [music_assistant.spotify_connect] Received metadata on webservice [Spotify Connect [None]]:
{'event_time': '2026-01-19 19:13:58.934901', 'event': 'playing', 'track_id': '4xF4ZBGPZKxECeDFrqSAG4', 'position_ms': '5678'}
2026-01-19 19:13:59.126 DEBUG (MainThread) [music_assistant.spotify_connect] Already the active Spotify device
2026-01-19 19:13:59.545 DEBUG (MainThread) [music_assistant.spotify_connect] [Spotify Connect [None]] [2026-01-19T19:13:59Z ERROR librespot_playback::player] Audio Sink Error On Write: <StdoutSink> Broken pipe (os error 32)

@prydie
Copy link
Contributor Author

prydie commented Jan 21, 2026

Another set of logs from trying to start the music this morning and it exercising this patch: repro.log

@MarvinSchenkel
Copy link
Contributor

I don't dislike this approach, but have you tried to investigate the root cause of those broken pipes? Might be better to prevent broken pipes rather than 'turning it off and on again'?

@prydie
Copy link
Contributor Author

prydie commented Jan 22, 2026

I for sure think that this could become a bandaid that removes friction that incentivises us to be more rigorous around edge case bugs. Ultimately though if we get into the state where librespot is emitting this log our only path to recovery is restarting the process whether that's manual or not.

I'm running with this patch deployed at the moment and I'm exercising it a couple of times a day at least (I'll circle back and quantify that properly when I'm in front of a computer). Being practical this patch is what's making the set-up usable.

Some ideas on what information would be useful to log before restarting the provider would be welcome. Especially if we can get visibility into the ffmpeg side of things.

A couple of places I saw sleeps for 1s with comments about avoiding races which drew my attention but I haven't had time to reason properly about their implications.

I've managed to get into states where I've had multiple librespot processes referencing the same named pipe which is definitely problematic but haven't pinpointed the proximate cause.

My gut feeling is that a degree of the problems relate to how we handle switching the player/the player changing state. My set-up is physically being built out still and is pretty heterogeneous (what old/cheap speakers can I hook up to an esp32 in this space kind of thing). The churn in that kind of environment is non-trivial.

I'm hoping to make some time over the weekend to take more of a look at this so any thoughts/ pointers would be great 😁

@prydie
Copy link
Contributor Author

prydie commented Jan 23, 2026

And as if I scripted it, this morning when I tried to start playback Spotify was pausing after 1-2s of playback and this is what I see on the server:

andrew@home-nas:~$ docker top music-assistant-server | grep libre
root                18798               20631               0                   Jan22               ?                   00:03:05            /app/venv/lib/python3.13/site-packages/music_assistant/providers/spotify/bin/librespot-linux-x86_64 --name Holly's Room --cache /data/.cache/spotify_connect--wYSNBGF3 --disable-audio-cache --bitrate 320 --backend pipe --device /tmp/spotify_connect--wYSNBGF3 --dither none --mixer passthrough --volume-ctrl passthrough --initial-volume 51 --enable-volume-normalisation --onevent /app/venv/lib/python3.13/site-packages/music_assistant/providers/spotify_connect/events.py --emit-sink-events
root                28559               20631               0                   Jan22               ?                   00:02:17            /app/venv/lib/python3.13/site-packages/music_assistant/providers/spotify/bin/librespot-linux-x86_64 --name Playroom Stereo --cache /data/.cache/spotify_connect--pZhtGRPN --disable-audio-cache --bitrate 320 --backend pipe --device /tmp/spotify_connect--pZhtGRPN --dither none --mixer passthrough --volume-ctrl passthrough --initial-volume 60 --enable-volume-normalisation --onevent /app/venv/lib/python3.13/site-packages/music_assistant/providers/spotify_connect/events.py --emit-sink-events
andrew@home-nas:~$ docker top music-assistant-server | grep ffmpeg
root                4007                20631               0                   Jan21               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--pZhtGRPN -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                8339                20631               0                   Jan20               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                8354                20631               0                   Jan20               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                10534               20631               0                   Jan21               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                12092               20631               0                   08:54               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--pZhtGRPN -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                17000               20631               0                   Jan20               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                17867               20631               0                   Jan20               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                18777               20631               0                   Jan22               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--wYSNBGF3 -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -
root                28544               20631               0                   Jan22               ?                   00:00:00            ffmpeg -hide_banner -loglevel info -nostats -ignore_unknown -protocol_whitelist file,hls,http,https,tcp,tls,crypto,pipe,data,fd,rtp,udp,concat -probesize 8096 -analyzeduration 500000 -y -re -ac 2 -channel_layout stereo -ar 44100 -acodec pcm_s16le -f s16le -acodec pcm_s16le -i /tmp/spotify_connect--pZhtGRPN -af alimiter=limit=-2dB:level=false:asc=true -ar 44100 -acodec pcm_s16le -f wav -

Here are the MA logs: ma.log

Edit: I ran the below to kill all of the ffmpeg processes and was able to restart playback. Interestingly that was without librespot getting the IO error (i.e. without a librespot process restart).

docker top music-assistant-server | grep ffmpeg | tr -s ' ' | cut -d' ' -f 2 | sudo xargs kill -9

@MarvinSchenkel
Copy link
Contributor

I think we need to go about this differently. Those broken pipes are a result of something else that goes wrong. Simply restarting the provider just feels hacky and does not address the root cause.

We need to figure out what is causing these hanging ffmpeg proceses / multiple ffmpeg processes referencing the same named pipe. I have a hunch this could have something to do with automatic switching of players.

Can you try to figure out what triggers these states? Then we could solve that and prevent broken pipe errors in the first place.

@MarvinSchenkel
Copy link
Contributor

Marking this PR as draft so we can keep track of which PRs needs our attention. Please mark as 'Ready for review' when you want us to have another look 🙏 .

@MarvinSchenkel MarvinSchenkel marked this pull request as draft January 28, 2026 08:47
@prydie
Copy link
Contributor Author

prydie commented Jan 28, 2026

I'll do my best to get back to this.

That said, when I started trying to do multi-room more seriously my ESP32 S3s completely failed to stay in sync with the forced PCM on the Spotify Connect plug-in. As such, I moved to the Spotify plugin and figured out DNS / Traefik so that my wife could be persuaded off the Spotify app.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants