I use volumio primarily as a Spotify and Qobuz Connect end point. I run Rpi4 with a USB DAC with hardware mixer volume control. I have tried the last few rev 3.x and beta 4.x volumio distros.
Qobuz has been rock solid. Pausing, unpausing, advancing thru playlists all works fine. Spotify also works well after a clean reboot of the RPi. The problem occurs when I first play a tune with Qobuz Connect, pause the tune and then launch a tune from a Spotify client. The song via Spotify either looks like it is going to start to play but never does or starts and stutters.
As a fix, I loaded the FusionDSP plugin, enabled the plugin but DISABLED the effects. With the FusionDSP plugin loaded I can use Spotify and Qobuz Connect interchangable and I don’t have pausing or stuttering issues at all.
Why do I need the FusionDSP plugin to get reliable Spotify and Qobuz Connect streaming?
log file below. Without FusionDSP plugin. play spotify (good), play qobuz (good), play spotify (no connect/no audio)
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined
info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates
info: Received Get System Version
info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
info: Received Get System Info
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
time="2025-07-25T18:39:56-04:00" level=trace msg="sent dealer ping"
time="2025-07-25T18:39:56-04:00" level=trace msg="received dealer pong"
time="2025-07-25T18:39:58-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
time="2025-07-25T18:39:58-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1131"
time="2025-07-25T18:40:04-04:00" level=debug msg="handling transfer player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:40:04-04:00" level=debug msg="renewing login5 access token"
time="2025-07-25T18:40:04-04:00" level=info msg="authenticated Login5 as 1222445125"
time="2025-07-25T18:40:04-04:00" level=debug msg="resolved context of track" uri="spotify:artist:2TpAfGX0XNikAg5QjrbbvE"
time="2025-07-25T18:40:04-04:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:2TpAfGX0XNikAg5QjrbbvE"
time="2025-07-25T18:40:04-04:00" level=trace msg="fetched new page 1 with 31 items (list: 41)" uri="spotify:artist:2TpAfGX0XNikAg5QjrbbvE"
time="2025-07-25T18:40:04-04:00" level=debug msg="loading track (paused: true, position: 30399ms)" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:04-04:00" level=trace msg="emitting websocket event: will_play"
SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","play_origin":"com.spotify.service.freetierartist"}}
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345"
time="2025-07-25T18:40:04-04:00" level=debug msg="selected format OGG_VORBIS_320 (7f9dccb5646692ff6b325576d84836e938bbcc35)" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="requested aes key for file 7f9dccb5646692ff6b325576d84836e938bbcc35, gid: 46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1340"
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1114"
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched first chunk of 17, total size is 8664706 bytes" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid"
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=trace msg="seek to 30399ms (diff: 109ms, samples: 1340595, bytes: 1240238)" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="created new output device"
time="2025-07-25T18:40:04-04:00" level=info msg="loaded track \"Shine Silently\" (paused: true, position: 30399ms, duration: 219466ms, prefetched: false)" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:04-04:00" level=trace msg="emitting websocket event: metadata"
time="2025-07-25T18:40:04-04:00" level=trace msg="emitting websocket event: active"
time="2025-07-25T18:40:04-04:00" level=debug msg="sending successful reply for dealer request"
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
time="2025-07-25T18:40:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","name":"Shine Silently","artist_names":["Nils Lofgren"],"album_name":"The Best","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","position":30399,"duration":219466,"release_date":"year:1979 month:1 day:1","track_number":8,"disc_number":1}}
SPOTIFY: received: {"type":"active","data":null}
info: Aligning Spotify Volume to Volumio Volume
info: CoreCommandRouter::volumioGetState
info: Setting Spotify Volume from Volumio: 38
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched chunk 5/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched chunk 4/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:04-04:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:05-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:05-04:00" level=trace msg="emitting websocket event: paused"
SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","play_origin":"com.spotify.service.freetierartist"}}
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"pause","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":30399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: SETTING SPOTIFY VOLUME 38
info: Sending Spotify command with payload to local API: /player/volume
time="2025-07-25T18:40:06-04:00" level=debug msg="update volume to 24903/65535"
time="2025-07-25T18:40:07-04:00" level=debug msg="put connect state because VOLUME_CHANGED"
time="2025-07-25T18:40:07-04:00" level=trace msg="emitting websocket event: volume"
SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}}
SPOTIFY: RECEIVED SPOTIFY VOLUME 38
time="2025-07-25T18:40:14-04:00" level=debug msg="handling resume player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:40:14-04:00" level=trace msg="seek to 30399ms (diff: 109ms, samples: 1340595, bytes: 1240238)" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:14-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames"
time="2025-07-25T18:40:14-04:00" level=debug msg="resume track at 30290ms"
time="2025-07-25T18:40:14-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:14-04:00" level=trace msg="scheduling prefetch in 159s"
time="2025-07-25T18:40:14-04:00" level=debug msg="sending successful reply for dealer request"
time="2025-07-25T18:40:14-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:14-04:00" level=trace msg="emitting websocket event: playing"
SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","play_origin":"com.spotify.service.freetierartist"}}
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"play","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":30399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"play","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":30399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
time="2025-07-25T18:40:22-04:00" level=debug msg="fetched chunk 6/16, size: 524288" uri="spotify:track:46tIHRMuDQkBiUUKV3IIOu"
time="2025-07-25T18:40:24-04:00" level=debug msg="handling pause player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:40:24-04:00" level=debug msg="pause track at 40466ms"
Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service...
[system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.359' (uid=0 pid=25873 comm="timedatectl show --property=NTPSynchronized --valu")
Starting systemd-timedated.service - Time & Date Service...
time="2025-07-25T18:40:24-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:24-04:00" level=debug msg="sending successful reply for dealer request"
time="2025-07-25T18:40:24-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:24-04:00" level=trace msg="emitting websocket event: paused"
SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","play_origin":"com.spotify.service.freetierartist"}}
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"pause","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":40399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
[system] Successfully activated service 'org.freedesktop.timedate1'
Started systemd-timedated.service - Time & Date Service.
Time is already synchronized.
setdatetime-helper.timer.service: Deactivated successfully.
Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service.
time="2025-07-25T18:40:26-04:00" level=trace msg="sent dealer ping"
time="2025-07-25T18:40:26-04:00" level=trace msg="received dealer pong"
20250725 18:40:35.868 [25789.25792] INFO SampleApp: API endpoint invoked: get-connect-info
20250725 18:40:36.165 [25789.25792] INFO SampleApp: API endpoint invoked: connect-to-qconnect
20250725 18:40:36.166 [25789.25789] INFO EndpointManager: [0xceba98]: Updating API endpoint
20250725 18:40:36.166 [25789.25789] INFO EndpointManager: [0xceba98]: Updating QConnect endpoint
20250725 18:40:36.166 [25789.25789] INFO ActiveStateManager: [0xceaab0]: Setting new active state: active
20250725 18:40:36.166 [25789.25789] INFO PlaybackSessionManager: [0xcebe88]: Starting playback session maintenance
20250725 18:40:36.166 [25789.25789] INFO HttpDownloader: [0xcec078]: Downloading content from: https://www.qobuz.com/api.json/0.2/session/start
20250725 18:40:36.167 [25789.25789] INFO CloudClient: [0xcec6f8]: Connecting to the cloud
20250725 18:40:36.167 [25789.25789] INFO SampleApp: Renderer is now active
20250725 18:40:36.305 [25789.25789] INFO CloudClient: [0xcec6f8]: Connection established
20250725 18:40:36.305 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Authenticate message
20250725 18:40:36.305 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Subscribe message
20250725 18:40:36.305 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending JoinSession message
20250725 18:40:36.305 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending VolumeChanged message
20250725 18:40:36.305 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending VolumeMuted message
20250725 18:40:36.305 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending MaxAudioQualityChanged message
20250725 18:40:36.305 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetActive message: active
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetState message:
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playing state: Paused
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playback position: 47388
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Queue version: 1.1
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Current track: TID: 15842161, QID: 0, Context UUID: 74c034cb-60ec-433f-bf46-79197be90763
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Next track: TID: 131263909, QID: 1, Context UUID: 74c034cb-60ec-433f-bf46-79197be90763
20250725 18:40:36.361 [25789.25789] INFO MediaEngine: [0xcec120]: Stopping playback, clearing tracks
20250725 18:40:36.361 [25789.25789] INFO MediaEngine: [0xcec120]: Initiating playback
20250725 18:40:36.361 [25789.25789] INFO RendererActionAvailabilityManager: [0xcec7b0]: Renderer action 'Next' is available
20250725 18:40:36.361 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetLoopMode message: Off
20250725 18:40:36.361 [25789.25789] INFO PlaybackControlsManager: [0xcec4f8]: Setting new loop mode: Off
20250725 18:40:36.361 [25789.25789] INFO PlaybackSessionManager: [0xcebe88]: Playback session has been refreshed
20250725 18:40:36.361 [25789.25789] INFO MediaEngine: [0xcec120]: Setting current track: 15842161, initial offset: 47388ms
20250725 18:40:36.361 [25789.25789] INFO AudioStreamManager: [0xcec208]: Clearing all streams
20250725 18:40:36.361 [25789.25789] INFO AudioStreamManager: [0xcec208]: New stream: 1
20250725 18:40:36.361 [25789.25789] INFO HttpDownloader: [0xcef320]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=5e715e8bb0858623667eb6a84fcff2c0&request_ts=1753483236&track_id=15842161
20250725 18:40:36.361 [25789.25789] INFO HttpDownloader: [0xdfedb0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=15842161
20250725 18:40:36.362 [25789.25789] INFO HttpDownloader: [0xcf2270]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=ebbc72630e8931fd58b705a6f5457c4b&request_ts=1753483236&track_id=15842161
20250725 18:40:36.362 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 1]: Running audio stream
20250725 18:40:36.362 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetShuffleMode message: disabled
20250725 18:40:36.362 [25789.25789] INFO PlaybackControlsManager: [0xcec4f8]: Setting new shuffle mode: disabled
20250725 18:40:36.362 [25789.25789] INFO MediaEngine: [0xcec120]: Setting next track: 131263909
20250725 18:40:36.362 [25789.25789] INFO AudioStreamManager: [0xcec208]: New stream: 2
20250725 18:40:36.362 [25789.25789] INFO HttpDownloader: [0xcf2678]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=0191ad3da9f118f0ae5ccf6b52999ed9&request_ts=1753483236&track_id=131263909
20250725 18:40:36.362 [25789.25789] INFO HttpDownloader: [0xcf2a30]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=131263909
20250725 18:40:36.362 [25789.25789] INFO HttpDownloader: [0xcf7c80]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=4028815e5642851a1e4d9c26d8abbedf&request_ts=1753483236&track_id=131263909
20250725 18:40:36.362 [25789.25789] INFO MediaEngine: [0xcec120]: Waiting for current stream to start before starting audio renderer
20250725 18:40:36.585 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 1]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=1192891&eid=15842161&fmt=6&profile=raw&app_id=174516466&cid=1246861&etsp=1753486836&hmac=dWOypi-nNGv38Xxwc4xZ_oWgblY
20250725 18:40:36.585 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Starting URL audio source, initial position: 47388ms, URL: https://streaming-qobuz-std.akamaized.net/file?uid=1192891&eid=15842161&fmt=6&profile=raw&app_id=174516466&cid=1246861&etsp=1753486836&hmac=dWOypi-nNGv38Xxwc4xZ_oWgblY
20250725 18:40:36.585 [25789.25789] INFO ContentFetcher: [0xea5100]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=1192891&eid=15842161&fmt=6&profile=raw&app_id=174516466&cid=1246861&etsp=1753486836&hmac=dWOypi-nNGv38Xxwc4xZ_oWgblY, offset: 0
20250725 18:40:36.585 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 1]: stream information have been fetched
20250725 18:40:36.585 [25789.25789] INFO AudioRenderer: [0xcec340]: Starting audio renderer, initial playback state: Paused
20250725 18:40:36.585 [25789.25789] INFO SampleApp: [Stream 1]: New audio stream (starting from 47387ms)
info: CoreCommandRouter::volumioGetState
info: QobuzConnect: setActiveState()
info: CoreCommandRouter::volumioGetState
info: QobuzConnect: Set Qobuz connect default volume to 38
info: CoreCommandRouter::volumioGetState
20250725 18:40:36.588 [25789.25789] INFO VolumeManager: [0xcec588]: Setting new playback volume: 38
info: CoreCommandRouter::volumioGetState
info: QobuzConnect: Stopping currently active service
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::serviceStop
info: CoreCommandRouter::serviceStop
info: Spotify Stop
SPOTIFY: SPOTIFY STOP
SPOTIFY: {"status":"pause","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","codec":"ogg","seek":40399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":38,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"}
info: Sending Spotify command to local API: /player/pause
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::syncState stateService stop
info: CoreStateMachine::syncState currentStatus pause
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: QobuzConnect: setActiveState(): setting Volatile state to qobuzconnect
info: QobuzConnect: setActiveState() completed, send playback confirmation
20250725 18:40:36.604 [25789.25789] INFO SampleApp: Initiating playback, initial state: Paused
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
20250725 18:40:36.613 [25789.25789] INFO SampleApp: Playback state changed: Paused
20250725 18:40:36.613 [25789.25789] INFO ProtocolHandler: [0xcec860]: Need to send state update
20250725 18:40:36.613 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending StateUpdated message
20250725 18:40:36.613 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
20250725 18:40:36.613 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending FileAudioQualityChanged message
20250725 18:40:36.613 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
20250725 18:40:36.613 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending DeviceAudioQualityChanged message
20250725 18:40:36.614 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
time="2025-07-25T18:40:36-04:00" level=debug msg="pause track at 40954ms"
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 2]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=1192891&eid=131263909&fmt=7&profile=raw&app_id=174516466&cid=1246861&etsp=1753486836&hmac=uyQbSiwslPqorWpAoFQcyJEMa28
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 1]: Metadata became available:
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Title: Solo Dancing
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Artist: Indiana
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Album: Solo Dancing
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Album art URL: https://static.qobuz.com/images/covers/52/80/0886444478052_600.jpg
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 2]: stream information have been fetched
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: [Stream 2]: Metadata became available:
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Title: My Baby Just Cares For Me (Live)
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Artist: Jeff Goldblum & The Mildred Snitzer Orchestra
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Album: The Capitol Studios Sessions (Live)
20250725 18:40:36.666 [25789.25789] INFO AudioStreamManager: [0xcec208]: Album art URL: https://static.qobuz.com/images/covers/3a/m3/i2uwm8pr6m33a_600.jpg
20250725 18:40:36.666 [25789.25789] INFO SampleApp: [Stream 1]: Stream metadata became available:
20250725 18:40:36.666 [25789.25789] INFO SampleApp: Title: Solo Dancing
20250725 18:40:36.666 [25789.25789] INFO SampleApp: Artist: Indiana
20250725 18:40:36.666 [25789.25789] INFO SampleApp: Album: Solo Dancing
20250725 18:40:36.666 [25789.25789] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/52/80/0886444478052_600.jpg
info: CoreCommandRouter::volumioGetState
time="2025-07-25T18:40:36-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
20250725 18:40:36.738 [25789.25789] INFO SampleApp: Playback volume changed: 38
20250725 18:40:36.738 [25789.25789] INFO ProtocolHandler: [0xcec860]: Volume changed: 38
20250725 18:40:36.738 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending VolumeChanged message
20250725 18:40:36.738 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
info: CoreCommandRouter::volumioGetState
time="2025-07-25T18:40:36-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:40:36-04:00" level=trace msg="emitting websocket event: paused"
SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","play_origin":"com.spotify.service.freetierartist"}}
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"pause","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":40399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
20250725 18:40:36.772 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Content info extracted
20250725 18:40:36.772 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Size: 27409308
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Stream info:
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Total samples: 11230212
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Sample rate: 44100
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Channel count: 2
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Bits per sample: 16
20250725 18:40:36.773 [25789.25896] INFO AudioDecoder: [0xeeb568]: Duration: 254653
20250725 18:40:36.774 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Audio properties have changed
20250725 18:40:36.774 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Seeking input stream to byte offset: 3862281
20250725 18:40:36.774 [25789.25789] INFO ContentFetcher: [0xea5100]: Adjusting download offset to: 3862281
20250725 18:40:36.864 [25789.25789] INFO UrlAudioSource: [0xea4e18]: Seeking input stream to byte offset: 3893118
20250725 18:40:36.864 [25789.25789] INFO ContentFetcher: [0xea5100]: Adjusting download offset to: 3893118
20250725 18:40:39.076 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetState message:
20250725 18:40:39.077 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playing state: Playing
20250725 18:40:39.077 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playback position:
20250725 18:40:39.077 [25789.25789] INFO ProtocolHandler: [0xcec860]: Queue version:
20250725 18:40:39.077 [25789.25789] INFO ProtocolHandler: [0xcec860]: Current track:
20250725 18:40:39.077 [25789.25789] INFO ProtocolHandler: [0xcec860]: Next track:
20250725 18:40:39.077 [25789.25789] INFO MediaEngine: [0xcec120]: Resuming playback
20250725 18:40:39.077 [25789.25789] INFO AudioRenderer: [0xcec340]: Resuming audio renderer
20250725 18:40:39.077 [25789.25789] INFO SampleApp: Resuming playback
20250725 18:40:39.089 [25789.25789] INFO SampleApp: Playback state changed: Playing
20250725 18:40:39.090 [25789.25789] INFO StreamingEventReporter: [0xcecc78]: Reporting streaming started event
20250725 18:40:39.090 [25789.25789] INFO HttpDownloader: [0xceccd0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingStart
info: CoreCommandRouter::volumioGetState
20250725 18:40:39.090 [25789.25789] INFO ProtocolHandler: [0xcec860]: Need to send state update
20250725 18:40:39.090 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending StateUpdated message
20250725 18:40:39.090 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
20250725 18:40:49.090 [25789.25789] INFO ProtocolHandler: [0xcec860]: Need to send state update
20250725 18:40:49.090 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending StateUpdated message
20250725 18:40:49.090 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
systemd-timedated.service: Deactivated successfully.
time="2025-07-25T18:40:56-04:00" level=trace msg="sent dealer ping"
time="2025-07-25T18:40:56-04:00" level=trace msg="received dealer pong"
20250725 18:40:59.091 [25789.25789] INFO ProtocolHandler: [0xcec860]: Need to send state update
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
20250725 18:40:59.093 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending StateUpdated message
20250725 18:40:59.093 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Received SetState message:
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playing state: Paused
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Playback position:
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Queue version:
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Current track:
20250725 18:40:59.446 [25789.25789] INFO ProtocolHandler: [0xcec860]: Next track:
20250725 18:40:59.446 [25789.25789] INFO MediaEngine: [0xcec120]: Pausing playback
20250725 18:40:59.446 [25789.25789] INFO AudioRenderer: [0xcec340]: Pausing audio renderer
20250725 18:40:59.446 [25789.25789] INFO SampleApp: Pausing playback
20250725 18:40:59.446 [25789.25789] INFO SampleApp: Playback state changed: Paused
20250725 18:40:59.447 [25789.25789] INFO StreamingEventReporter: [0xcecc78]: Reporting streaming ended event
20250725 18:40:59.447 [25789.25789] INFO HttpDownloader: [0xceccd0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingEndJson
20250725 18:40:59.447 [25789.25789] INFO ProtocolHandler: [0xcec860]: Need to send state update
20250725 18:40:59.447 [25789.25789] INFO QConnectMessageSender: [0xde3df8]: Sending StateUpdated message
20250725 18:40:59.447 [25789.25789] INFO QwspMessageSender: [0xde3de8]: Sending Payload message
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
time="2025-07-25T18:41:06-04:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update
time="2025-07-25T18:41:06-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 162"
time="2025-07-25T18:41:09-04:00" level=debug msg="handling play player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:41:09-04:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DX4JAvHpjipBk"
time="2025-07-25T18:41:09-04:00" level=trace msg="fetched new page 0 with 99 items (list: 99)" uri="spotify:playlist:37i9dQZF1DX4JAvHpjipBk"
time="2025-07-25T18:41:09-04:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:41:09-04:00" level=trace msg="emitting websocket event: will_play"
SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5FMyXeZ0reYloRTiCkPprT","play_origin":"playlist/ondemand"}}
time="2025-07-25T18:41:09-04:00" level=debug msg="selected format OGG_VORBIS_320 (7cbcf752013481a969059f1a9da7fe690991b98f)" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=debug msg="requested aes key for file 7cbcf752013481a969059f1a9da7fe690991b98f, gid: 5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=debug msg="fetched first chunk of 15, total size is 7513581 bytes" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed setting stream for spotify:track:5FMyXeZ0reYloRTiCkPprT: ALSA error at snd_pcm_open: Device or resource busy"
time="2025-07-25T18:41:09-04:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:09-04:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:19-04:00" level=debug msg="handling pause player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:41:19-04:00" level=debug msg="pause track at 0ms"
time="2025-07-25T18:41:19-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:41:19-04:00" level=debug msg="sending successful reply for dealer request"
time="2025-07-25T18:41:19-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-07-25T18:41:19-04:00" level=trace msg="emitting websocket event: paused"
SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5FMyXeZ0reYloRTiCkPprT","play_origin":"playlist/ondemand"}}
info: Spotify is playing in volatile mode
info: CoreStateMachine::setConsumeUpdateService undefined
SPOTIFY: UNSET VOLATILE
SPOTIFY: {"status":"pause","title":"Solo Dancing","artist":"Indiana","album":"Solo Dancing","albumart":"https://static.qobuz.com/images/covers/52/80/0886444478052_600.jpg","uri":"","trackType":"qobuz","codec":"","seek":66895,"duration":255,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"consume":false,"volume":38,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"qobuzconnect"}
info: Setting Spotify stop after unset volatile call
SPOTIFY: PUSH STATE SPOTIFY
SPOTIFY: {"status":"pause","service":"spop","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","seek":40399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::volumioGetState
SPOTIFY: RECEIVED VOLUMIO VOLUME 38
info: Spotify Stop
SPOTIFY: SPOTIFY STOP
SPOTIFY: {"status":"pause","title":"Shine Silently","artist":"Nils Lofgren","album":"The Best","albumart":"https://i.scdn.co/image/ab67616d00001e02c69a5a264ca31d4e7def55fb","uri":"spotify:track:46tIHRMuDQkBiUUKV3IIOu","trackType":"spotify","codec":"ogg","seek":40399,"duration":219,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":38,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"}
time="2025-07-25T18:41:20-04:00" level=debug msg="handling resume player command from 83e6f8aee69e4e24124b99475d6756d010ba37ae"
time="2025-07-25T18:41:20-04:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:20-04:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5FMyXeZ0reYloRTiCkPprT"
time="2025-07-25T18:41:20-04:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: Device or resource busy"
time="2025-07-25T18:41:26-04:00" level=trace msg="received accesspoint ping"
time="2025-07-25T18:41:26-04:00" level=trace msg="received accesspoint pong ack"
time="2025-07-25T18:41:26-04:00" level=trace msg="sent dealer ping"
time="2025-07-25T18:41:26-04:00" level=trace msg="received dealer pong"