Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DX5Hl0iWtr5b3" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4wBbmJvKozJN" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4tMC2JTe3MCG" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:19 chambre go-librespot[1640]: time="2026-08-29T11:30:19+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4jXFV0KMR1gU" Aug 29 11:30:23 chambre go-librespot[1640]: time="2026-08-29T11:30:23+02:00" level=trace msg="received accesspoint ping" Aug 29 11:30:23 chambre go-librespot[1640]: time="2026-08-29T11:30:23+02:00" level=trace msg="received accesspoint pong ack" Aug 29 11:30:23 chambre go-librespot[1640]: time="2026-08-29T11:30:23+02:00" level=trace msg="sent dealer ping" Aug 29 11:30:23 chambre go-librespot[1640]: time="2026-08-29T11:30:23+02:00" level=trace msg="received dealer pong" Aug 29 11:30:43 chambre go-librespot[1640]: time="2026-08-29T11:30:43+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:43 chambre go-librespot[1640]: time="2026-08-29T11:30:43+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E8AS4XuFGlPLQ" Aug 29 11:30:44 chambre go-librespot[1640]: time="2026-08-29T11:30:44+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:44 chambre go-librespot[1640]: time="2026-08-29T11:30:44+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E8IO5E9Ij8rJm" Aug 29 11:30:52 chambre go-librespot[1640]: time="2026-08-29T11:30:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Aug 29 11:30:52 chambre go-librespot[1640]: time="2026-08-29T11:30:52+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E8ON40tgN6rNU" Aug 29 11:30:53 chambre go-librespot[1640]: time="2026-08-29T11:30:53+02:00" level=trace msg="sent dealer ping" Aug 29 11:30:53 chambre go-librespot[1640]: time="2026-08-29T11:30:53+02:00" level=trace msg="received dealer pong" Aug 29 11:31:05 chambre volumio[1235]: info: CorePlayQueue::getTrack 8 Aug 29 11:31:05 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:05 chambre volumio[1235]: info: Prefetching next song Aug 29 11:31:05 chambre volumio[1235]: info: [1787995865057] ControllerSpotify::prefetch Aug 29 11:31:05 chambre volumio[1235]: info: Sending Spotify command with payload to local API: /player/add_to_queue Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=trace msg="prefetch as soon as possible" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="prefetching next track" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="selected format OGG_VORBIS_96 (c592113322479faf44fa21deb7521e1906a59197)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="requested aes key for file c592113322479faf44fa21deb7521e1906a59197, gid: 0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="fetched first chunk of 7, total size is 3631328 bytes" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=info msg="prefetched track \"Unfinished Sympathy - 2012 Mix/Master\" (duration: 308426ms)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="fetched chunk 1/6, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="fetched chunk 3/6, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:05 chambre go-librespot[1640]: time="2026-08-29T11:31:05+02:00" level=debug msg="fetched chunk 2/6, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=trace msg="emitting websocket event: not_playing" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:09 chambre volumio[1235]: error: Failed to decode event: not_playing Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=trace msg="emitting websocket event: will_play" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=info msg="loaded track \"Unfinished Sympathy - 2012 Mix/Master\" (paused: false, position: 0ms, duration: 308426ms, prefetched: true)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=trace msg="scheduling prefetch in 279s" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:09 chambre go-librespot[1640]: time="2026-08-29T11:31:09+02:00" level=trace msg="emitting websocket event: playing" Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::servicePushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 8 Aug 29 11:31:09 chambre volumio[1235]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Unfinished Sympathy - 2012 Mix/Master","artist":"Massive Attack, Shara Nelson","album":"Blue Lines (2012 Mix/Master)","albumart":"https://i.scdn.co/image/ab67616d00001e02af5beb00d940f5ede452d6b5","uri":"spotify:track:0j5FJJOmmnXPd0XajFWkMF","trackType":"spotify","seek":0,"duration":308,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 29 11:31:09 chambre volumio[1235]: verbose: CURRENT POSITION 8 Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::syncState stateService play Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::syncState currentStatus play Aug 29 11:31:09 chambre volumio[1235]: info: Received an update from plugin. extracting info from payload Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 8 Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 8 Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.536+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=157309 volume=58 Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.537+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:6DYLWAdxEJvwWmT7EkeDkX title=Charmed Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.541+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=157309 volume=58 Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.542+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:6DYLWAdxEJvwWmT7EkeDkX title=Charmed Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::startPlaybackTimer Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::servicePushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:09 chambre volumio[1235]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Unfinished Sympathy - 2012 Mix/Master","artist":"Massive Attack, Shara Nelson","album":"Blue Lines (2012 Mix/Master)","albumart":"https://i.scdn.co/image/ab67616d00001e02af5beb00d940f5ede452d6b5","uri":"spotify:track:0j5FJJOmmnXPd0XajFWkMF","trackType":"spotify","seek":1000,"duration":308,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Aug 29 11:31:09 chambre volumio[1235]: verbose: CURRENT POSITION 9 Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::syncState stateService play Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::syncState currentStatus play Aug 29 11:31:09 chambre volumio[1235]: info: Received an update from plugin. extracting info from payload Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:09 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:09 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:09 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.830+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=1000 volume=58 Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.830+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:0j5FJJOmmnXPd0XajFWkMF title="Unfinished Sympathy - 2012 Mix/Master" Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.832+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=1000 volume=58 Aug 29 11:31:09 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:09.833+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:0j5FJJOmmnXPd0XajFWkMF title="Unfinished Sympathy - 2012 Mix/Master" Aug 29 11:31:10 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:10 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:10 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 11:31:10 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:10 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:10.067+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=1285 volume=58 Aug 29 11:31:10 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:10.068+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:0j5FJJOmmnXPd0XajFWkMF title="Unfinished Sympathy - 2012 Mix/Master" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="handling play player command from 1fd5d2bb7b94455b554bd972856c3802c60f4d42" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="resolved context of track" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="emitting websocket event: will_play" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="selected format OGG_VORBIS_96 (cfcd4ff8c8cea6083b7d3354c8dbadef3967029e)" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="requested aes key for file cfcd4ff8c8cea6083b7d3354c8dbadef3967029e, gid: 0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="fetched first chunk of 7, total size is 3347496 bytes" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=info msg="loaded track \"Bring It On\" (paused: false, position: 0ms, duration: 241176ms, prefetched: false)" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="scheduling prefetch in 211s" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=trace msg="emitting websocket event: playing" Aug 29 11:31:11 chambre volumio[1235]: info: Spotify is playing in volatile mode Aug 29 11:31:11 chambre volumio[1235]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 11:31:11 chambre volumio[1235]: info: Setting Spotify stop after unset volatile call Aug 29 11:31:11 chambre volumio[1235]: info: CoreCommandRouter::servicePushState Aug 29 11:31:11 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:11 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="handling update_context player command from 1fd5d2bb7b94455b554bd972856c3802c60f4d42" Aug 29 11:31:11 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="fetched chunk 2/6, size: 524288" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="fetched chunk 1/6, size: 524288" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:11 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:11.885+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=0 volume=58 Aug 29 11:31:11 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:11.887+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:0P8BGAx1To25L12bfUCWvU title="Bring It On" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 11:31:11 chambre go-librespot[1640]: time="2026-08-29T11:31:11+02:00" level=debug msg="fetched chunk 3/6, size: 524288" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:12 chambre volumio[1235]: info: CoreCommandRouter::servicePushState Aug 29 11:31:12 chambre volumio[1235]: info: CoreStateMachine::pushState Aug 29 11:31:12 chambre volumio[1235]: info: CoreCommandRouter::volumioPushState Aug 29 11:31:12 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:12.179+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" state=STATUS_PLAYING positionMs=0 volume=58 Aug 29 11:31:12 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:12.180+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" id=spotify:track:0P8BGAx1To25L12bfUCWvU title="Bring It On" Aug 29 11:31:12 chambre volumio[1235]: info: Spotify Stop Aug 29 11:31:23 chambre go-librespot[1640]: time="2026-08-29T11:31:23+02:00" level=trace msg="sent dealer ping" Aug 29 11:31:23 chambre go-librespot[1640]: time="2026-08-29T11:31:23+02:00" level=trace msg="received dealer pong" Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.060+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.153+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=http://pushupdates.volumio.org duration=90.247787ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.220+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=159.923133ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.416+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://www.googleapis.com duration=351.77453ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.449+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://securetoken.googleapis.com duration=386.457569ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.463+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=http://cddb.volumio.org duration=398.362296ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.530+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=464.915629ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.551+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://google.com duration=487.361964ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.565+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://functions.volumio.cloud duration=501.334075ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.568+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://functions.volumio.cloud duration=503.443959ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.568+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://database.volumio.cloud duration=504.644735ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.678+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=http://plugins.volumio.org duration=614.39856ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.979+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=918.154239ms Aug 29 11:31:38 chambre volumio5-onboarding[1560]: time=2026-08-29T11:31:38.979+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.129.75:49263,00:00:00:00:00:00%01 @ 0x17fc720" latency=35.689961ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=915.16764ms Aug 29 11:31:39 chambre volumio[1235]: verbose: New Socket.io Connection to 192.168.129.99 from 192.168.129.75 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: 6 Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::volumioGetVisibleSources Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::volumioGetState Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 29 11:31:39 chambre volumio[1235]: info: Received Get System Info Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 11:31:39 chambre volumio[1235]: info: Discovery: Getting this device information Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::volumioGetState Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::volumioGetState Aug 29 11:31:39 chambre volumio[1235]: info: Listing playlists Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::volumioGetQueue Aug 29 11:31:39 chambre volumio[1235]: info: CoreStateMachine::getQueue Aug 29 11:31:39 chambre volumio[1235]: info: CorePlayQueue::getQueue Aug 29 11:31:39 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 11:31:40 chambre volumio[1235]: info: Discovery: Getting this device information Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::volumioGetState Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 11:31:40 chambre volumio[1235]: verbose: New Socket.io Connection to 192.168.129.99:3000 from 192.168.129.75 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 11:31:40 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 11:31:49 chambre go-librespot[1640]: time="2026-08-29T11:31:49+02:00" level=debug msg="fetched chunk 4/6, size: 524288" uri="spotify:track:0P8BGAx1To25L12bfUCWvU" Aug 29 11:31:53 chambre go-librespot[1640]: time="2026-08-29T11:31:53+02:00" level=trace msg="sent dealer ping" Aug 29 11:31:53 chambre go-librespot[1640]: time="2026-08-29T11:31:53+02:00" level=trace msg="received dealer pong" Aug 29 11:31:53 chambre volumio[1235]: info: CorePlayQueue::getTrack 9 Aug 29 11:31:53 chambre volumio[1235]: info: CoreCommandRouter::executeOnPlugin: spop , goto Aug 29 11:31:54 chambre volumio[1235]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 11:31:54 chambre volumio[1235]: TypeError: Cannot read properties of undefined (reading 'url') Aug 29 11:31:54 chambre volumio[1235]: at /data/plugins/music_service/spop/index.js:2410:60 Aug 29 11:31:54 chambre volumio[1235]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Aug 29 11:31:54 chambre volumio[1235]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 11:31:55 chambre sudo[3520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 11:30' Aug 29 11:31:55 chambre sudo[3520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"