Aug 28 17:50:03 primo volumio[3414]: info: CoreCommandRouter::volumioNext Aug 28 17:50:03 primo volumio[3414]: info: CoreStateMachine::next Aug 28 17:50:03 primo volumio[3414]: info: Spotify next Aug 28 17:50:03 primo volumio[3414]: info: Sending Spotify command to local API: /player/next Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:03 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:6QZo2TgclkUMwJgggi8QSQ","play_origin":"playlist/ondemand"}} Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (fb52435c34356907c4a7d471295ff2717e6e5a73)" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=debug msg="requested aes key for file fb52435c34356907c4a7d471295ff2717e6e5a73, gid: 6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=debug msg="fetched first chunk of 25, total size is 13014806 bytes" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:03 primo kernel: spdif_a is set to disable Aug 28 17:50:03 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:03 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:03 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:03 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:03 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:03 primo go-librespot[3952]: time="2026-08-28T17:50:03+02:00" level=info msg="loaded track \"Africa\" (paused: false, position: 0ms, duration: 295071ms, prefetched: false)" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:03 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:03 primo kernel: spdif_a is set to enable Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=trace msg="scheduling prefetch in 265s" Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6QZo2TgclkUMwJgggi8QSQ","name":"Africa","artist_names":["TOTO"],"album_name":"Greatest Hits: 40 Trips Around The Sun","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0224f2b77982c78a9322848d9c","position":0,"duration":295071,"release_date":"year:2018 month:2 day:9","track_number":17,"disc_number":1}} Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:6QZo2TgclkUMwJgggi8QSQ","resume":false,"play_origin":"playlist/ondemand"}} Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Africa","artist":"TOTO","album":"Greatest Hits: 40 Trips Around The Sun","albumart":"https://i.scdn.co/image/ab67616d00001e0224f2b77982c78a9322848d9c","uri":"spotify:track:6QZo2TgclkUMwJgggi8QSQ","trackType":"spotify","seek":0,"duration":295,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:04 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:04 primo go-librespot[3952]: time="2026-08-28T17:50:04+02:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:6QZo2TgclkUMwJgggi8QSQ" Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:04 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:04 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:04 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:04.479+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:04 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:04.481+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6QZo2TgclkUMwJgggi8QSQ title=Africa Aug 28 17:50:04 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:04 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Africa","artist":"TOTO","album":"Greatest Hits: 40 Trips Around The Sun","albumart":"https://i.scdn.co/image/ab67616d00001e0224f2b77982c78a9322848d9c","uri":"spotify:track:6QZo2TgclkUMwJgggi8QSQ","trackType":"spotify","seek":1000,"duration":295,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:04 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:04 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:04 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:04 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:04 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:04.777+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=1000 volume=47 Aug 28 17:50:04 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:04.777+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6QZo2TgclkUMwJgggi8QSQ title=Africa Aug 28 17:50:04 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:04 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:04 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:08 primo volumio[3414]: info: CoreCommandRouter::volumioNext Aug 28 17:50:08 primo volumio[3414]: info: CoreStateMachine::next Aug 28 17:50:08 primo volumio[3414]: info: Spotify next Aug 28 17:50:08 primo volumio[3414]: info: Sending Spotify command to local API: /player/next Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:08 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:4yugZvBYaoREkJKtbG08Qr","play_origin":"playlist/ondemand"}} Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=debug msg="selected format OGG_VORBIS_320 (614f2a1dbbc26e248ac3abc2ab6fa683bcf9b971)" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=debug msg="requested aes key for file 614f2a1dbbc26e248ac3abc2ab6fa683bcf9b971, gid: 4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=debug msg="fetched first chunk of 19, total size is 9787852 bytes" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo go-librespot[3952]: time="2026-08-28T17:50:08+02:00" level=info msg="loaded track \"Take It Easy - 2013 Remaster\" (paused: false, position: 0ms, duration: 211577ms, prefetched: false)" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:08 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:08 primo kernel: spdif_a is set to disable Aug 28 17:50:08 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:08 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:08 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:08 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:08 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:09 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:09 primo kernel: spdif_a is set to enable Aug 28 17:50:09 primo go-librespot[3952]: time="2026-08-28T17:50:09+02:00" level=trace msg="sent dealer ping" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="scheduling prefetch in 181s" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:10 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4yugZvBYaoREkJKtbG08Qr","name":"Take It Easy - 2013 Remaster","artist_names":["Eagles"],"album_name":"Eagles (2013 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c13acd642ba9f6f5f127aa1b","position":0,"duration":211577,"release_date":"year:1972 month:6 day:1","track_number":1,"disc_number":1}} Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="received accesspoint ping" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="received dealer pong" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:4yugZvBYaoREkJKtbG08Qr" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:10 primo go-librespot[3952]: time="2026-08-28T17:50:10+02:00" level=trace msg="received accesspoint pong ack" Aug 28 17:50:10 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:4yugZvBYaoREkJKtbG08Qr","resume":false,"play_origin":"playlist/ondemand"}} Aug 28 17:50:10 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:10 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Take It Easy - 2013 Remaster","artist":"Eagles","album":"Eagles (2013 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02c13acd642ba9f6f5f127aa1b","uri":"spotify:track:4yugZvBYaoREkJKtbG08Qr","trackType":"spotify","seek":1000,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:10 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:10 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:10 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:10 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:10 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:10 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:10 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:10 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:10.825+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=1000 volume=47 Aug 28 17:50:10 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:10.827+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:4yugZvBYaoREkJKtbG08Qr title="Take It Easy - 2013 Remaster" Aug 28 17:50:10 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:10 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:10 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:11 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:11 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Take It Easy - 2013 Remaster","artist":"Eagles","album":"Eagles (2013 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02c13acd642ba9f6f5f127aa1b","uri":"spotify:track:4yugZvBYaoREkJKtbG08Qr","trackType":"spotify","seek":1000,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:11 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:11 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:11 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:11 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:11 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:11 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:11 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:11.122+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=1000 volume=47 Aug 28 17:50:11 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:11.123+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:4yugZvBYaoREkJKtbG08Qr title="Take It Easy - 2013 Remaster" Aug 28 17:50:11 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:11 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:11 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:14 primo volumio[3414]: info: CoreCommandRouter::volumioNext Aug 28 17:50:14 primo volumio[3414]: info: CoreStateMachine::next Aug 28 17:50:14 primo volumio[3414]: info: Spotify next Aug 28 17:50:14 primo volumio[3414]: info: Sending Spotify command to local API: /player/next Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:14 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:6ybViy2qrO9sIi41EgRJgx","play_origin":"playlist/ondemand"}} Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=debug msg="selected format OGG_VORBIS_320 (70278747b9ff6aa27c0321d834792be103489b8b)" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=debug msg="requested aes key for file 70278747b9ff6aa27c0321d834792be103489b8b, gid: 1zNXF2svmdlNxfS5XeNUgr" Aug 28 17:50:14 primo go-librespot[3952]: time="2026-08-28T17:50:14+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=debug msg="fetched first chunk of 15, total size is 7534936 bytes" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=info msg="loaded track \"Don't Know Why\" (paused: false, position: 0ms, duration: 186146ms, prefetched: false)" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:15 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:15 primo kernel: spdif_a is set to disable Aug 28 17:50:15 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:15 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:15 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:15 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:15 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:15 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:15 primo kernel: spdif_a is set to enable Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=trace msg="scheduling prefetch in 156s" Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:15 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1zNXF2svmdlNxfS5XeNUgr","name":"Don't Know Why","artist_names":["Norah Jones"],"album_name":"Come Away With Me","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027862811f80ae629373954f0d","position":0,"duration":186146,"release_date":"year:2002 month:2 day:26","track_number":1,"disc_number":1}} Aug 28 17:50:15 primo go-librespot[3952]: time="2026-08-28T17:50:15+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:16 primo go-librespot[3952]: time="2026-08-28T17:50:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:16 primo go-librespot[3952]: time="2026-08-28T17:50:16+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:6ybViy2qrO9sIi41EgRJgx","resume":false,"play_origin":"playlist/ondemand"}} Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Don't Know Why","artist":"Norah Jones","album":"Come Away With Me","albumart":"https://i.scdn.co/image/ab67616d00001e027862811f80ae629373954f0d","uri":"spotify:track:1zNXF2svmdlNxfS5XeNUgr","trackType":"spotify","seek":0,"duration":186,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:16 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:16 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:16 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:16 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:16.127+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:16 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:16.131+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:1zNXF2svmdlNxfS5XeNUgr title="Don't Know Why" Aug 28 17:50:16 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:16 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Don't Know Why","artist":"Norah Jones","album":"Come Away With Me","albumart":"https://i.scdn.co/image/ab67616d00001e027862811f80ae629373954f0d","uri":"spotify:track:1zNXF2svmdlNxfS5XeNUgr","trackType":"spotify","seek":0,"duration":186,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:16 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:16 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:16 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:16 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:16 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:16.425+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:16 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:16.425+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:1zNXF2svmdlNxfS5XeNUgr title="Don't Know Why" Aug 28 17:50:16 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:16 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:16 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:16 primo go-librespot[3952]: time="2026-08-28T17:50:16+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:16 primo go-librespot[3952]: time="2026-08-28T17:50:16+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:29 primo go-librespot[3952]: time="2026-08-28T17:50:29+02:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:6ybViy2qrO9sIi41EgRJgx" Aug 28 17:50:32 primo volumio[3414]: info: Preload queue cleared Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::ClearQueue Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::stop Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::serviceStop Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::serviceStop Aug 28 17:50:32 primo volumio[3414]: info: Spotify Stop Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: SPOTIFY STOP Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: {"status":"play","title":"Don't Know Why","artist":"Norah Jones","album":"Come Away With Me","albumart":"https://i.scdn.co/image/ab67616d00001e027862811f80ae629373954f0d","uri":"spotify:track:1zNXF2svmdlNxfS5XeNUgr","trackType":"spotify","codec":"ogg","seek":0,"duration":186,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":47,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Aug 28 17:50:32 primo volumio[3414]: info: Sending Spotify command to local API: /player/pause Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::clearPlayQueue Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::saveQueue Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPushQueue Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::addQueueItems Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::addQueueItems Aug 28 17:50:32 primo volumio[3414]: info: Preload queue cleared Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3mhOmh4tRKsMfnRmgZfeBm Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3mhOmh4tRKsMfnRmgZfeBm Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:0eKyHwckh9vQb8ncZ2DXCs Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:0eKyHwckh9vQb8ncZ2DXCs Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:2a1iMaoWQ5MnvLFBDv4qkf Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:2a1iMaoWQ5MnvLFBDv4qkf Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPushQueue Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::saveQueue Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::updateTrackBlock Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrackBlock Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPlay Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::play index 2 Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::addQueueItems Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::addQueueItems Aug 28 17:50:32 primo volumio[3414]: info: Preload queue cleared Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:6qLEOZvf5gI7kWE63JE7p3 Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:6qLEOZvf5gI7kWE63JE7p3 Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:7bu0znpSbTks0O6I98ij0W Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:7bu0znpSbTks0O6I98ij0W Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3Nf8oGn1okobzjDcFCvT6n Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3Nf8oGn1okobzjDcFCvT6n Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:2hnMS47jN0etwvFPzYk11f Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:2hnMS47jN0etwvFPzYk11f Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:57bgtoPSgt236HzfBOd8kj Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:57bgtoPSgt236HzfBOd8kj Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:7gWE3j4HZmrXQiGkQxrRt0 Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:7gWE3j4HZmrXQiGkQxrRt0 Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3CVDronuSnhguSUguPoseM Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3CVDronuSnhguSUguPoseM Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:0KPWi8mDRagwxnwaA0di8a Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:0KPWi8mDRagwxnwaA0di8a Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:4tFIVbgaIQCgGxcLBdsljv Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:4tFIVbgaIQCgGxcLBdsljv Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:0nnwn7LWHCAu09jfuH1xTA Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:0nnwn7LWHCAu09jfuH1xTA Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:7jmHyHMEqm9MJWiMAneF05 Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:7jmHyHMEqm9MJWiMAneF05 Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:7iN1s7xHE4ifF5povM6A48 Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:7iN1s7xHE4ifF5povM6A48 Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3Uvx1TO0Kg5HgGPk58lHXv Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3Uvx1TO0Kg5HgGPk58lHXv Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:1ju7EsSGvRybSNEsRvc7qY Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:1ju7EsSGvRybSNEsRvc7qY Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3ftHrCjsTUPLgI48m67byk Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3ftHrCjsTUPLgI48m67byk Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:0QnONzv3TvHAWk294h6DaQ Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:0QnONzv3TvHAWk294h6DaQ Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3CtphwpjC0XjIVpLFvGiQR Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3CtphwpjC0XjIVpLFvGiQR Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:1JLn8RhQzHz3qDqsChcmBl Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:1JLn8RhQzHz3qDqsChcmBl Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:1G8jae4jD8mwkXdodqHsBM Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:1G8jae4jD8mwkXdodqHsBM Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:4RCWB3V8V0dignt99LZ8vH Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:4RCWB3V8V0dignt99LZ8vH Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:6YIggUJW3ttAAPRdnki8RM Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:6YIggUJW3ttAAPRdnki8RM Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3xIaUb1WsnrqbJo6CsJMLO Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3xIaUb1WsnrqbJo6CsJMLO Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:2o49Twc3qrNMOt8gq9W06L Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:2o49Twc3qrNMOt8gq9W06L Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:3BQHpFgAp4l80e1XslIjNI Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:3BQHpFgAp4l80e1XslIjNI Aug 28 17:50:32 primo volumio[3414]: info: Adding Item to queue: spotify:track:7N2rGqOwOL4RoGMQuUQnfK Aug 28 17:50:32 primo volumio[3414]: info: Using cached record of: spotify:track:7N2rGqOwOL4RoGMQuUQnfK Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::stop Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::stPlaybackTimer Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::updateTrackBlock Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrackBlock Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrack 8 Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrack 8 Aug 28 17:50:32 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:32 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::serviceStop Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrack 8 Aug 28 17:50:32 primo volumio[3414]: info: ControllerMpd::stop Aug 28 17:50:32 primo volumio[3414]: verbose: ControllerMpd::sendMpdCommand stop Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPushQueue Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::saveQueue Aug 28 17:50:32 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:32.338+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:32 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:32.339+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id= title= Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::updateTrackBlock Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrackBlock Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:32 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:32 primo volumio[3414]: info: sendMpdCommand stop took 36 milliseconds Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::play index undefined Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrack 2 Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::startPlaybackTimer Aug 28 17:50:32 primo volumio[3414]: info: CorePlayQueue::getTrack 2 Aug 28 17:50:32 primo volumio[3414]: info: [1787932232373] ControllerSpotify::clearAddPlayTrack Aug 28 17:50:32 primo volumio[3414]: info: Sending Spotify command with payload to local API: /player/play Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="pause track at 16652ms" Aug 28 17:50:32 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:32 primo kernel: spdif_a is set to disable Aug 28 17:50:32 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:32 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 28 17:50:32 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 28 17:50:32 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 28 17:50:32 primo volumio[3414]: info: MCU Signalled Playback Inactive Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=trace msg="emitting websocket event: paused" Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:4HwhvGWYnnyTRaWrcSJI7j","uri":"spotify:track:6ybViy2qrO9sIi41EgRJgx","play_origin":"playlist/ondemand"}} Aug 28 17:50:32 primo volumio[3414]: info: Spotify is playing in volatile mode Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: UNSET VOLATILE Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":47,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":false,"repeatSingle":false,"consume":false} Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:32 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:32 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:32 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:32 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:32 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:32.528+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PAUSED positionMs=0 volume=47 Aug 28 17:50:32 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:32.529+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id= title= Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:32 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="resolved context of track" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="shuffled context with seed 11655019463671399727 (len: 1, keep: -1)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:32 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","play_origin":"go-librespot"}} Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="selected format OGG_VORBIS_320 (521df1f6d8a5258e13781144b2eb48bd5e1ba282)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=debug msg="requested aes key for file 521df1f6d8a5258e13781144b2eb48bd5e1ba282, gid: 2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:32 primo go-librespot[3952]: time="2026-08-28T17:50:32+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=debug msg="fetched first chunk of 23, total size is 11613596 bytes" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:33 primo kernel: aml_tdm_open Aug 28 17:50:33 primo kernel: Not init audio effects Aug 28 17:50:33 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 28 17:50:33 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:33 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:33 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:33 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d06b218, id(1), clksel(1) Aug 28 17:50:33 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 28 17:50:33 primo kernel: dump_pcm_setting(ffffffc03d06b218) Aug 28 17:50:33 primo kernel: pcm_mode(1) Aug 28 17:50:33 primo kernel: sysclk(11289600) Aug 28 17:50:33 primo kernel: sysclk_bclk_ratio(4) Aug 28 17:50:33 primo kernel: bclk(2822400) Aug 28 17:50:33 primo kernel: bclk_lrclk_ratio(64) Aug 28 17:50:33 primo kernel: lrclk(44100) Aug 28 17:50:33 primo kernel: tx_mask(0x3) Aug 28 17:50:33 primo kernel: rx_mask(0x3) Aug 28 17:50:33 primo kernel: slots(2) Aug 28 17:50:33 primo kernel: slot_width(32) Aug 28 17:50:33 primo kernel: lane_mask_in(0x2) Aug 28 17:50:33 primo kernel: lane_mask_out(0x1) Aug 28 17:50:33 primo kernel: lane_oe_mask_in(0x0) Aug 28 17:50:33 primo kernel: lane_oe_mask_out(0x0) Aug 28 17:50:33 primo kernel: lane_lb_mask_in(0x0) Aug 28 17:50:33 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:33 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:33 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:33 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 28 17:50:33 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 28 17:50:33 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 28 17:50:33 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:33 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:33 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:33 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:33 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:33 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:33 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:33 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:33 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:33 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:33 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:33 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:33 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:33 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:33 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02: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, PCM format = FLOAT_LE" Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=info msg="loaded track \"High and Dry\" (paused: false, position: 0ms, duration: 257480ms, prefetched: false)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:33 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:33 primo kernel: spdif_a is set to enable Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=trace msg="scheduling prefetch in 227s" Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:33 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","name":"High and Dry","artist_names":["Radiohead"],"album_name":"The Bends","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","position":0,"duration":257480,"release_date":"year:1995 month:3 day:13","track_number":3,"disc_number":1}} Aug 28 17:50:33 primo go-librespot[3952]: time="2026-08-28T17:50:33+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:34 primo go-librespot[3952]: time="2026-08-28T17:50:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:34 primo go-librespot[3952]: time="2026-08-28T17:50:34+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","resume":false,"play_origin":"go-librespot"}} Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"High and Dry","artist":"Radiohead","album":"The Bends","albumart":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","trackType":"spotify","seek":0,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:34 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:34 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:34 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:34 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:34.450+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:34 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:34.452+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:2a1iMaoWQ5MnvLFBDv4qkf title="High and Dry" Aug 28 17:50:34 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:34 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:34 primo go-librespot[3952]: time="2026-08-28T17:50:34+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:34 primo volumio[3414]: info: MCU Signalled Playback Active Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"High and Dry","artist":"Radiohead","album":"The Bends","albumart":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","trackType":"spotify","seek":0,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:34 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:34 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:34 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:34 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:34 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:34.748+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:34 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:34.749+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:2a1iMaoWQ5MnvLFBDv4qkf title="High and Dry" Aug 28 17:50:34 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:34 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:34 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:35 primo go-librespot[3952]: time="2026-08-28T17:50:35+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:38 primo volumio[3414]: info: CoreCommandRouter::volumioNext Aug 28 17:50:38 primo volumio[3414]: info: CoreStateMachine::next Aug 28 17:50:38 primo volumio[3414]: info: Spotify next Aug 28 17:50:38 primo volumio[3414]: info: Sending Spotify command to local API: /player/next Aug 28 17:50:38 primo go-librespot[3952]: time="2026-08-28T17:50:38+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:38 primo go-librespot[3952]: time="2026-08-28T17:50:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:38 primo go-librespot[3952]: time="2026-08-28T17:50:38+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:38 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","play_origin":"go-librespot"}} Aug 28 17:50:38 primo go-librespot[3952]: time="2026-08-28T17:50:38+02:00" level=debug msg="selected format OGG_VORBIS_320 (521df1f6d8a5258e13781144b2eb48bd5e1ba282)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:38 primo go-librespot[3952]: time="2026-08-28T17:50:38+02:00" level=debug msg="requested aes key for file 521df1f6d8a5258e13781144b2eb48bd5e1ba282, gid: 2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:39 primo go-librespot[3952]: time="2026-08-28T17:50:39+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:39 primo go-librespot[3952]: time="2026-08-28T17:50:39+02:00" level=trace msg="sent dealer ping" Aug 28 17:50:39 primo go-librespot[3952]: time="2026-08-28T17:50:39+02:00" level=debug msg="fetched first chunk of 23, total size is 11613596 bytes" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:39 primo go-librespot[3952]: time="2026-08-28T17:50:39+02:00" level=trace msg="received dealer pong" Aug 28 17:50:39 primo go-librespot[3952]: time="2026-08-28T17:50:39+02:00" level=info msg="loaded track \"High and Dry\" (paused: true, position: 0ms, duration: 257480ms, prefetched: false)" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:39 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:39 primo kernel: spdif_a is set to disable Aug 28 17:50:39 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:39 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 28 17:50:39 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 28 17:50:39 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","name":"High and Dry","artist_names":["Radiohead"],"album_name":"The Bends","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","position":0,"duration":257480,"release_date":"year:1995 month:3 day:13","track_number":3,"disc_number":1}} Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: {"status":"stop","service":"spop","title":"High and Dry","artist":"Radiohead","album":"The Bends","albumart":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","trackType":"spotify","seek":0,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=trace msg="emitting websocket event: stopped" Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:40 primo volumio[3414]: info: CorePlayQueue::getTrack 2 Aug 28 17:50:40 primo volumio[3414]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"High and Dry","artist":"Radiohead","album":"The Bends","albumart":"https://i.scdn.co/image/ab67616d00001e029293c743fa542094336c5e12","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","trackType":"spotify","seek":0,"duration":257,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:40 primo volumio[3414]: verbose: CURRENT POSITION 2 Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::syncState stateService stop Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::syncState currentStatus play Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::play index undefined Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.313+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.314+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:2a1iMaoWQ5MnvLFBDv4qkf title="High and Dry" Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.316+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.317+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:2a1iMaoWQ5MnvLFBDv4qkf title="High and Dry" Aug 28 17:50:40 primo volumio[3414]: info: CorePlayQueue::getTrack 3 Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::startPlaybackTimer Aug 28 17:50:40 primo volumio[3414]: info: CorePlayQueue::getTrack 3 Aug 28 17:50:40 primo volumio[3414]: info: [1787932240329] ControllerSpotify::clearAddPlayTrack Aug 28 17:50:40 primo volumio[3414]: info: Sending Spotify command with payload to local API: /player/play Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.340+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.340+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:2a1iMaoWQ5MnvLFBDv4qkf title="High and Dry" Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:40 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:40 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:40 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:40 primo volumio[3414]: info: MCU Signalled Playback Inactive Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=trace msg="emitting websocket event: paused" Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","uri":"spotify:track:2a1iMaoWQ5MnvLFBDv4qkf","play_origin":"go-librespot"}} Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:40 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:40 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:40 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.785+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PAUSED positionMs=0 volume=47 Aug 28 17:50:40 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:40.786+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id= title= Aug 28 17:50:40 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:40 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="resolved context of track" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="shuffled context with seed 521360257172965094 (len: 1, keep: -1)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:40 primo go-librespot[3952]: time="2026-08-28T17:50:40+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:41 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","play_origin":"go-librespot"}} Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:2a1iMaoWQ5MnvLFBDv4qkf" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=debug msg="selected format OGG_VORBIS_320 (62ef3318659bfacec73128342a0fb6ff0a0a870d)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=debug msg="requested aes key for file 62ef3318659bfacec73128342a0fb6ff0a0a870d, gid: 6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:41 primo go-librespot[3952]: time="2026-08-28T17:50:41+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=debug msg="fetched first chunk of 16, total size is 7883708 bytes" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02: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, PCM format = FLOAT_LE" Aug 28 17:50:42 primo kernel: aml_tdm_open Aug 28 17:50:42 primo kernel: Not init audio effects Aug 28 17:50:42 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 28 17:50:42 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:42 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:42 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:42 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d06b218, id(1), clksel(1) Aug 28 17:50:42 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 28 17:50:42 primo kernel: dump_pcm_setting(ffffffc03d06b218) Aug 28 17:50:42 primo kernel: pcm_mode(1) Aug 28 17:50:42 primo kernel: sysclk(11289600) Aug 28 17:50:42 primo kernel: sysclk_bclk_ratio(4) Aug 28 17:50:42 primo kernel: bclk(2822400) Aug 28 17:50:42 primo kernel: bclk_lrclk_ratio(64) Aug 28 17:50:42 primo kernel: lrclk(44100) Aug 28 17:50:42 primo kernel: tx_mask(0x3) Aug 28 17:50:42 primo kernel: rx_mask(0x3) Aug 28 17:50:42 primo kernel: slots(2) Aug 28 17:50:42 primo kernel: slot_width(32) Aug 28 17:50:42 primo kernel: lane_mask_in(0x2) Aug 28 17:50:42 primo kernel: lane_mask_out(0x1) Aug 28 17:50:42 primo kernel: lane_oe_mask_in(0x0) Aug 28 17:50:42 primo kernel: lane_oe_mask_out(0x0) Aug 28 17:50:42 primo kernel: lane_lb_mask_in(0x0) Aug 28 17:50:42 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:42 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:42 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:42 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 28 17:50:42 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 28 17:50:42 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 28 17:50:42 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:42 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:42 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:42 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:42 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:42 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:42 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:42 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:42 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:42 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:42 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:42 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:42 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:42 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:42 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=info msg="loaded track \"Interstate Love Song - 2019 Remaster\" (paused: false, position: 1ms, duration: 194853ms, prefetched: false)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=trace msg="scheduling prefetch in 165s" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:42 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","name":"Interstate Love Song - 2019 Remaster","artist_names":["Stone Temple Pilots"],"album_name":"Purple (2019 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","position":1,"duration":194853,"release_date":"year:1994 month:6 day:7","track_number":4,"disc_number":1}} Aug 28 17:50:42 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:42 primo kernel: spdif_a is set to enable Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:42 primo go-librespot[3952]: time="2026-08-28T17:50:42+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:42 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","resume":false,"play_origin":"go-librespot"}} Aug 28 17:50:42 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:42 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Interstate Love Song - 2019 Remaster","artist":"Stone Temple Pilots","album":"Purple (2019 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","trackType":"spotify","seek":1,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:42 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:42 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:42 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:42 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:42 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:42 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:42 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:43 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:42.999+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=1 volume=47 Aug 28 17:50:43 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:43.000+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6qLEOZvf5gI7kWE63JE7p3 title="Interstate Love Song - 2019 Remaster" Aug 28 17:50:43 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:43 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:43 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:43 primo volumio[3414]: info: MCU Signalled Playback Active Aug 28 17:50:43 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:43 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Interstate Love Song - 2019 Remaster","artist":"Stone Temple Pilots","album":"Purple (2019 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","trackType":"spotify","seek":1,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:43 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:43 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:43 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:43 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:43 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:43 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:43 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:43.297+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=1 volume=47 Aug 28 17:50:43 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:43.298+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6qLEOZvf5gI7kWE63JE7p3 title="Interstate Love Song - 2019 Remaster" Aug 28 17:50:43 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:43 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:43 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:43 primo go-librespot[3952]: time="2026-08-28T17:50:43+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:43 primo go-librespot[3952]: time="2026-08-28T17:50:43+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:43 primo go-librespot[3952]: time="2026-08-28T17:50:43+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioNext Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::next Aug 28 17:50:45 primo volumio[3414]: info: Spotify next Aug 28 17:50:45 primo volumio[3414]: info: Sending Spotify command to local API: /player/next Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","play_origin":"go-librespot"}} Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="selected format OGG_VORBIS_320 (62ef3318659bfacec73128342a0fb6ff0a0a870d)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="requested aes key for file 62ef3318659bfacec73128342a0fb6ff0a0a870d, gid: 6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="fetched first chunk of 16, total size is 7883708 bytes" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:50:45 primo kernel: spdif_a is set to disable Aug 28 17:50:45 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:45 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 28 17:50:45 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 28 17:50:45 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=info msg="loaded track \"Interstate Love Song - 2019 Remaster\" (paused: true, position: 0ms, duration: 194853ms, prefetched: false)" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","name":"Interstate Love Song - 2019 Remaster","artist_names":["Stone Temple Pilots"],"album_name":"Purple (2019 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","position":0,"duration":194853,"release_date":"year:1994 month:6 day:7","track_number":4,"disc_number":1}} Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="emitting websocket event: stopped" Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: {"status":"stop","service":"spop","title":"Interstate Love Song - 2019 Remaster","artist":"Stone Temple Pilots","album":"Purple (2019 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:45 primo volumio[3414]: info: CorePlayQueue::getTrack 3 Aug 28 17:50:45 primo volumio[3414]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Interstate Love Song - 2019 Remaster","artist":"Stone Temple Pilots","album":"Purple (2019 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02fc90a8ed9924435d62235aa8","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:45 primo volumio[3414]: verbose: CURRENT POSITION 3 Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::syncState stateService stop Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::syncState currentStatus play Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::play index undefined Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.798+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.799+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6qLEOZvf5gI7kWE63JE7p3 title="Interstate Love Song - 2019 Remaster" Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.801+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.802+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6qLEOZvf5gI7kWE63JE7p3 title="Interstate Love Song - 2019 Remaster" Aug 28 17:50:45 primo volumio[3414]: info: CorePlayQueue::getTrack 4 Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::startPlaybackTimer Aug 28 17:50:45 primo volumio[3414]: info: CorePlayQueue::getTrack 4 Aug 28 17:50:45 primo volumio[3414]: info: [1787932245814] ControllerSpotify::clearAddPlayTrack Aug 28 17:50:45 primo volumio[3414]: info: Sending Spotify command with payload to local API: /player/play Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.830+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_STOPPED positionMs=0 volume=47 Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.831+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:6qLEOZvf5gI7kWE63JE7p3 title="Interstate Love Song - 2019 Remaster" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="emitting websocket event: paused" Aug 28 17:50:45 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:45 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:45 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","uri":"spotify:track:6qLEOZvf5gI7kWE63JE7p3","play_origin":"go-librespot"}} Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:45 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:45 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:45 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.881+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PAUSED positionMs=0 volume=47 Aug 28 17:50:45 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:45.882+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id= title= Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:45 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="resolved context of track" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="shuffled context with seed 4922393220774108832 (len: 1, keep: -1)" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6qLEOZvf5gI7kWE63JE7p3" Aug 28 17:50:45 primo volumio[3414]: info: MCU Signalled Playback Inactive Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:45 primo go-librespot[3952]: time="2026-08-28T17:50:45+02:00" level=trace msg="emitting websocket event: will_play" Aug 28 17:50:45 primo volumio[3414]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","play_origin":"go-librespot"}} Aug 28 17:50:46 primo go-librespot[3952]: time="2026-08-28T17:50:46+02:00" level=debug msg="selected format OGG_VORBIS_320 (ecb46def006a5f9fad928fb9321e5bcc4577af57)" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:46 primo go-librespot[3952]: time="2026-08-28T17:50:46+02:00" level=debug msg="requested aes key for file ecb46def006a5f9fad928fb9321e5bcc4577af57, gid: 7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:46 primo go-librespot[3952]: time="2026-08-28T17:50:46+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=debug msg="fetched first chunk of 19, total size is 9471436 bytes" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:47 primo kernel: aml_tdm_open Aug 28 17:50:47 primo kernel: Not init audio effects Aug 28 17:50:47 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 28 17:50:47 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:47 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:47 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:47 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d06b218, id(1), clksel(1) Aug 28 17:50:47 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 28 17:50:47 primo kernel: dump_pcm_setting(ffffffc03d06b218) Aug 28 17:50:47 primo kernel: pcm_mode(1) Aug 28 17:50:47 primo kernel: sysclk(11289600) Aug 28 17:50:47 primo kernel: sysclk_bclk_ratio(4) Aug 28 17:50:47 primo kernel: bclk(2822400) Aug 28 17:50:47 primo kernel: bclk_lrclk_ratio(64) Aug 28 17:50:47 primo kernel: lrclk(44100) Aug 28 17:50:47 primo kernel: tx_mask(0x3) Aug 28 17:50:47 primo kernel: rx_mask(0x3) Aug 28 17:50:47 primo kernel: slots(2) Aug 28 17:50:47 primo kernel: slot_width(32) Aug 28 17:50:47 primo kernel: lane_mask_in(0x2) Aug 28 17:50:47 primo kernel: lane_mask_out(0x1) Aug 28 17:50:47 primo kernel: lane_oe_mask_in(0x0) Aug 28 17:50:47 primo kernel: lane_oe_mask_out(0x0) Aug 28 17:50:47 primo kernel: lane_lb_mask_in(0x0) Aug 28 17:50:47 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 28 17:50:47 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 28 17:50:47 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 28 17:50:47 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 28 17:50:47 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 28 17:50:47 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 28 17:50:47 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:47 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:47 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:47 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:47 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:47 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:47 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:47 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:47 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:47 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:47 primo kernel: aml_tdm_prepare(), reset fddr Aug 28 17:50:47 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 28 17:50:47 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 28 17:50:47 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:50:47 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02: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, PCM format = FLOAT_LE" Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=info msg="loaded track \"Tonight, Tonight - Remastered 2012\" (paused: false, position: 0ms, duration: 254626ms, prefetched: false)" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:47 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 28 17:50:47 primo kernel: spdif_a is set to enable Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=trace msg="scheduling prefetch in 224s" Aug 28 17:50:47 primo go-librespot[3952]: time="2026-08-28T17:50:47+02:00" level=trace msg="emitting websocket event: metadata" Aug 28 17:50:47 primo volumio[3414]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","name":"Tonight, Tonight - Remastered 2012","artist_names":["The Smashing Pumpkins"],"album_name":"Mellon Collie And The Infinite Sadness (Deluxe Edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02431ac6e6f393acf475730ec6","position":0,"duration":254626,"release_date":"year:1995","track_number":2,"disc_number":1}} Aug 28 17:50:48 primo go-librespot[3952]: time="2026-08-28T17:50:48+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:48 primo go-librespot[3952]: time="2026-08-28T17:50:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 17:50:48 primo go-librespot[3952]: time="2026-08-28T17:50:48+02:00" level=trace msg="emitting websocket event: playing" Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","resume":false,"play_origin":"go-librespot"}} Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Tonight, Tonight - Remastered 2012","artist":"The Smashing Pumpkins","album":"Mellon Collie And The Infinite Sadness (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02431ac6e6f393acf475730ec6","uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","trackType":"spotify","seek":0,"duration":254,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:48 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:48 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:48 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:48 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:48.666+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:48 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:48.667+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:7bu0znpSbTks0O6I98ij0W title="Tonight, Tonight - Remastered 2012" Aug 28 17:50:48 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:48 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:50:48 primo volumio[3414]: info: MCU Signalled Playback Active Aug 28 17:50:48 primo go-librespot[3952]: time="2026-08-28T17:50:48+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: PUSH STATE SPOTIFY Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: {"status":"play","service":"spop","title":"Tonight, Tonight - Remastered 2012","artist":"The Smashing Pumpkins","album":"Mellon Collie And The Infinite Sadness (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02431ac6e6f393acf475730ec6","uri":"spotify:track:7bu0znpSbTks0O6I98ij0W","trackType":"spotify","seek":0,"duration":254,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::servicePushState Aug 28 17:50:48 primo volumio[3414]: info: CoreStateMachine::pushState Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::volumioPushState Aug 28 17:50:48 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:50:48 primo volumio[3414]: info: MRS: Pushing multiroomSync output update for this device Aug 28 17:50:48 primo volumio[3414]: info: MRS: Pushing multiroomSync output Aug 28 17:50:48 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:48.954+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" state=STATUS_PLAYING positionMs=0 volume=47 Aug 28 17:50:48 primo volumio5-onboarding[3834]: time=2026-08-28T17:50:48.956+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%06,192.168.1.200:60803 @ 0x2cfb920" id=spotify:track:7bu0znpSbTks0O6I98ij0W title="Tonight, Tonight - Remastered 2012" Aug 28 17:50:48 primo volumio[3414]: info: Signalling Playback active due to playback status change Aug 28 17:50:48 primo volumio[3414]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Aug 28 17:50:48 primo volumio[3414]: info: Updating RAAT Signal Path Aug 28 17:51:00 primo go-librespot[3952]: time="2026-08-28T17:51:00+02:00" level=debug msg="fetched chunk 4/18, size: 524288" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:51:03 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 17:51:03 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 28 17:51:09 primo go-librespot[3952]: time="2026-08-28T17:51:09+02:00" level=trace msg="sent dealer ping" Aug 28 17:51:09 primo go-librespot[3952]: time="2026-08-28T17:51:09+02:00" level=trace msg="received dealer pong" Aug 28 17:51:12 primo volumio[3414]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 28 17:51:14 primo go-librespot[3952]: time="2026-08-28T17:51:14+02:00" level=debug msg="fetched chunk 5/18, size: 524288" uri="spotify:track:7bu0znpSbTks0O6I98ij0W" Aug 28 17:51:22 primo volumio[3414]: info: Received OAUTH Data Aug 28 17:51:22 primo volumio[3414]: info: Executing Spotify Oauth Login Aug 28 17:51:22 primo volumio[3414]: info: Saving Spotify Refresh Token Aug 28 17:51:22 primo volumio[3414]: info: New Spotify access tokenBQB50ySG4F... Aug 28 17:51:22 primo volumio[3414]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 28 17:51:22 primo sudo[6406]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 17:51:22 primo sudo[6406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 17:51:22 primo sudo[6408]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 17:51:22 primo sudo[6408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 17:51:22 primo sudo[6406]: pam_unix(sudo:session): session closed for user root Aug 28 17:51:22 primo sudo[6408]: pam_unix(sudo:session): session closed for user root Aug 28 17:51:22 primo volumio[3414]: verbose: New Socket.io Connection to 192.168.1.131 from 192.168.1.200 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Aug 28 17:51:22 primo volumio[3414]: SPOTIFY: User informations: {"account_id":"NAI4aRPeYB","country":"SE","display_name":"garetharnold07","email":"teoinstallation@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/garetharnold07"},"followers":{"href":null,"total":6},"href":"https://api.spotify.com/v1/users/garetharnold07","id":"garetharnold07","images":[],"product":"premium","type":"user","uri":"spotify:user:garetharnold07"} Aug 28 17:51:22 primo volumio[3414]: info: Creating Spotify config file Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 17:51:22 primo volumio[3414]: info: Spotify config file written Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 17:51:22 primo volumio[3414]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 28 17:51:22 primo volumio[3414]: info: Received Get System Info Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 17:51:22 primo volumio[3414]: info: Discovery: Getting this device information Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:51:22 primo sudo[6414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 17:51:22 primo volumio[3414]: info: Listing playlists Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 17:51:22 primo sudo[6414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 17:51:22 primo systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 28 17:51:22 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 28 17:51:22 primo kernel: spdif_a is set to disable Aug 28 17:51:22 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 28 17:51:22 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 28 17:51:22 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 28 17:51:22 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 28 17:51:22 primo systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 28 17:51:22 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:22 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:22 primo sudo[6414]: pam_unix(sudo:session): session closed for user root Aug 28 17:51:22 primo go-librespot[6416]: go-librespot daemon starting... Aug 28 17:51:22 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 17:51:22 primo volumio[3414]: info: Connection to go-librespot Websocket closed Aug 28 17:51:22 primo go-librespot[6417]: time="2026-08-28T17:51:22+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 17:51:22 primo go-librespot[6417]: time="2026-08-28T17:51:22+02:00" level=debug msg="app state loaded" Aug 28 17:51:22 primo go-librespot[6417]: time="2026-08-28T17:51:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 17:51:22 primo volumio[3414]: info: New Spotify access tokenBQD3pCR-PJ... Aug 28 17:51:22 primo volumio[3414]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 28 17:51:23 primo volumio[3414]: SPOTIFY: User informations: {"account_id":"NAI4aRPeYB","country":"SE","display_name":"garetharnold07","email":"teoinstallation@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/garetharnold07"},"followers":{"href":null,"total":6},"href":"https://api.spotify.com/v1/users/garetharnold07","id":"garetharnold07","images":[],"product":"premium","type":"user","uri":"spotify:user:garetharnold07"} Aug 28 17:51:23 primo volumio[3414]: info: Spotify Successfully logged in Aug 28 17:51:23 primo volumio[3414]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 17:51:23 primo volumio[3414]: info: [1787932283014] CoreMusicLibrary::Adding element Spotify Aug 28 17:51:23 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 17:51:23 primo volumio[3414]: Cannot find translation for source Calm Radio Aug 28 17:51:23 primo volumio[3414]: Cannot find translation for source 80s80s Radio Aug 28 17:51:23 primo volumio[3414]: Cannot find translation for source Radio Paradise Aug 28 17:51:23 primo volumio[3414]: Cannot find translation for source Spotify Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=info msg="zeroconf server listening on port 33005" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="obtained new client token: AAE+nhnJfTESx1uI9Iuo1N7OKPO3lDMG4wW/Zwe4V9f8yLM8J9lnS+kJfhfhTtZzhKl8fGmHjNAiQ8jPUzSZkVZ3nz1m4NPr9HF8SsgXP4jYAIW56ba60kfGQAR+GELXlZcl0TCShpScvB4/ICX6yWCThXuvJEXjzVs2fNO6qD8dpk/oioZIC7lwtz8I0UCYvgnon5T3J0O8f0FlVs6PlcFollDbnqJZKV9ZavoJ64H7ToIvjnaNdw==" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="completed keyexchange" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=debug msg="completed challenge" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=info msg="authenticated AP" username="ga**********07" Aug 28 17:51:23 primo go-librespot[6417]: time="2026-08-28T17:51:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 17:51:23 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 17:51:23 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 17:51:24 primo volumio[3414]: info: Received Get System Info Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 17:51:24 primo volumio[3414]: info: Discovery: Getting this device information Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:51:24 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 17:51:25 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 17:51:25 primo volumio[3414]: info: Received Get System Info Aug 28 17:51:25 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 17:51:25 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 17:51:25 primo volumio[3414]: info: Discovery: Getting this device information Aug 28 17:51:25 primo volumio[3414]: info: CoreCommandRouter::volumioGetState Aug 28 17:51:25 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 17:51:25 primo volumio[3414]: info: Initializing connection to go-librespot Websocket Aug 28 17:51:25 primo volumio[3414]: info: go-librespot daemon successfully initialized Aug 28 17:51:25 primo volumio[3414]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 17:51:26 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 17:51:26 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:26 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:26 primo go-librespot[6452]: go-librespot daemon starting... Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=debug msg="app state loaded" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=info msg="zeroconf server listening on port 41521" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 17:51:26 primo go-librespot[6455]: time="2026-08-28T17:51:26+02:00" level=debug msg="obtained new client token: AAEIB3Zuoo+DWfsDWe9M0CFQ7nBo0ZHYMWBuhyTERnCohpJHKzzlhY9uscWYWSIwavZ69nYev6Vt7bYHkksvbHcWCGGegY9mBT42uyXkD7HLEKU/RCZ+l9qqae9L/vfLvtuEWjHPFiNo7JOrcsdGIgUsq3FK38o9o2dsCMc7UYQsZaeNvV0kAqQ+h4jjJbGaCuHWKYerxffHMcbDb4dqia/TRulLdq8ohE18ML+DAvBWxA9Xrk7fu2ij" Aug 28 17:51:27 primo go-librespot[6455]: time="2026-08-28T17:51:27+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 17:51:27 primo go-librespot[6455]: time="2026-08-28T17:51:27+02:00" level=debug msg="completed keyexchange" Aug 28 17:51:27 primo go-librespot[6455]: time="2026-08-28T17:51:27+02:00" level=debug msg="completed challenge" Aug 28 17:51:27 primo go-librespot[6455]: time="2026-08-28T17:51:27+02:00" level=info msg="authenticated AP" username="ga**********07" Aug 28 17:51:27 primo go-librespot[6455]: time="2026-08-28T17:51:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 17:51:27 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 17:51:27 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 17:51:28 primo volumio[3414]: info: Initializing connection to go-librespot Websocket Aug 28 17:51:28 primo volumio[3414]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 17:51:30 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 17:51:30 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:30 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:30 primo go-librespot[6471]: go-librespot daemon starting... Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=debug msg="app state loaded" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=info msg="zeroconf server listening on port 35449" Aug 28 17:51:30 primo go-librespot[6476]: time="2026-08-28T17:51:30+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=debug msg="obtained new client token: AAHJ26pnnHK2uBAgea66iF6i2NYPmZQz1UYhlEQHis7NexXF8jotNtnOGWa5V6vShvCCPmkN2whx4NQxgN0SAorSJj6e/mzCNYdJq+OscxXVH53O8yc0WJePuwLN8LU1wiuBAwTONgt77VIhbk/OIWJq/2klZ2x9m95FBiIUrMAqN9in35XbBBgCxvFHWe6p8zQc1vkzbXg0iYxha1ro9XRFBjdendpxFCEeRoIasZWOFBIM5xOrSchl" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=debug msg="completed keyexchange" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=debug msg="completed challenge" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=info msg="authenticated AP" username="ga**********07" Aug 28 17:51:31 primo go-librespot[6476]: time="2026-08-28T17:51:31+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 17:51:31 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 17:51:31 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 17:51:31 primo volumio[3414]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Aug 28 17:51:31 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Aug 28 17:51:31 primo volumio[3414]: info: Creating Spotify config file Aug 28 17:51:31 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 17:51:31 primo volumio[3414]: info: Spotify config file written Aug 28 17:51:31 primo sudo[6489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 17:51:31 primo sudo[6489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 17:51:31 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:31 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:31 primo sudo[6489]: pam_unix(sudo:session): session closed for user root Aug 28 17:51:31 primo go-librespot[6491]: go-librespot daemon starting... Aug 28 17:51:31 primo go-librespot[6492]: time="2026-08-28T17:51:31+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 17:51:31 primo go-librespot[6492]: time="2026-08-28T17:51:31+02:00" level=debug msg="app state loaded" Aug 28 17:51:31 primo go-librespot[6492]: time="2026-08-28T17:51:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 17:51:31 primo volumio[3414]: info: Initializing connection to go-librespot Websocket Aug 28 17:51:31 primo go-librespot[6492]: time="2026-08-28T17:51:31+02:00" level=debug msg="new websocket client" Aug 28 17:51:31 primo volumio[3414]: info: Connection to go-librespot Websocket established Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=info msg="zeroconf server listening on port 45887" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="obtained new client token: AAG7cE6fjRtL9tTKKwC1njdEnb/GHSjo5QEgXzVIFG05Ke1VDMBItPo4JfRAtGeNxwnlE5QxYHXNw4+amZOR4fk6Gyqm9pZDAmTxt7+1ApHF+jUtaYxfPwnoAUQlcha6OL+fINddLTusL9PxbENVi+85gSmZpJDcYRbTonjx0L8W+4W4Gbgh6NKPm2o0xt5eme+ZgznZTlhJw2MQtJbLuj2DYzwxVEnm+c6y1cX0Z45i4ndOrgSCVg==" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="completed keyexchange" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=debug msg="completed challenge" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=info msg="authenticated AP" username="ga**********07" Aug 28 17:51:32 primo go-librespot[6492]: time="2026-08-28T17:51:32+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 17:51:32 primo volumio[3414]: info: Connection to go-librespot Websocket closed Aug 28 17:51:32 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 17:51:32 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 17:51:32 primo volumio[3414]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 28 17:51:34 primo volumio[3414]: info: go-librespot daemon successfully initialized Aug 28 17:51:34 primo volumio[3414]: info: Getting Spotify volume Aug 28 17:51:34 primo volumio[3414]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 17:51:34 primo volumio[3414]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 17:51:34 primo volumio[3414]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 17:51:34 primo volumio[3414]: errno: -111, Aug 28 17:51:34 primo volumio[3414]: code: 'ECONNREFUSED', Aug 28 17:51:34 primo volumio[3414]: syscall: 'connect', Aug 28 17:51:34 primo volumio[3414]: address: '127.0.0.1', Aug 28 17:51:34 primo volumio[3414]: port: 9879, Aug 28 17:51:34 primo volumio[3414]: response: undefined Aug 28 17:51:34 primo volumio[3414]: } Aug 28 17:51:34 primo volumio[3414]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 17:51:35 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 17:51:35 primo systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:35 primo systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 17:51:35 primo go-librespot[6525]: go-librespot daemon starting... Aug 28 17:51:35 primo go-librespot[6526]: time="2026-08-28T17:51:35+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 17:51:35 primo go-librespot[6526]: time="2026-08-28T17:51:35+02:00" level=debug msg="app state loaded" Aug 28 17:51:35 primo go-librespot[6526]: time="2026-08-28T17:51:35+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 17:51:35 primo sudo[6533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 17:50' Aug 28 17:51:35 primo sudo[6533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="9ccd1247f8cab3c5d64c23a96d243f6bfa34d032" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun May 17 17:32:08 UTC 2026" VOLUMIO_VERSION="4.158" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="43d420a3aa41c50690ebfe378df38e2b"