Oct 13 20:30:02 rivoplus go-librespot[4930]: time="2026-10-13T20:30:02+02:00" level=debug msg="fetched chunk 14/16, size: 524288" uri="spotify:track:4mcZYzoGwPRDdhWVlygiHf" Oct 13 20:30:02 rivoplus systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 13 20:30:05 rivoplus systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 13 20:30:05 rivoplus systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 13 20:30:14 rivoplus go-librespot[4930]: time="2026-10-13T20:30:14+02:00" level=debug msg="fetched chunk 15/16, size: 524288" uri="spotify:track:4mcZYzoGwPRDdhWVlygiHf" Oct 13 20:30:26 rivoplus go-librespot[4930]: time="2026-10-13T20:30:26+02:00" level=debug msg="fetched chunk 16/16, size: 307347" uri="spotify:track:4mcZYzoGwPRDdhWVlygiHf" Oct 13 20:31:04 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:04 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:04 rivoplus volumio[3585]: info: Prefetching next song Oct 13 20:31:04 rivoplus volumio[3585]: info: [1791916264985] ControllerSpotify::prefetch Oct 13 20:31:04 rivoplus volumio[3585]: info: Sending Spotify command with payload to local API: /player/add_to_queue Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=trace msg="prefetch as soon as possible" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="prefetching next track" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="selected format OGG_VORBIS_320 (5c7a4f281af0cb3f5307d9577f403f05ad07ed20)" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="requested aes key for file 5c7a4f281af0cb3f5307d9577f403f05ad07ed20, gid: 5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="fetched first chunk of 13, total size is 6641817 bytes" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=info msg="prefetched track \"Don't Do Me Like That\" (duration: 161786ms)" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:05 rivoplus go-librespot[4930]: time="2026-10-13T20:31:05+02:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=trace msg="emitting websocket event: not_playing" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:4mcZYzoGwPRDdhWVlygiHf","uri":"spotify:track:4mcZYzoGwPRDdhWVlygiHf","play_origin":"go-librespot"}} Oct 13 20:31:08 rivoplus volumio[3585]: error: Failed to decode event: not_playing Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=trace msg="emitting websocket event: will_play" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=debug msg="track has no narration" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4mcZYzoGwPRDdhWVlygiHf","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","play_origin":"go-librespot"}} Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=info msg="loaded track \"Don't Do Me Like That\" (paused: false, position: 0ms, duration: 161786ms, prefetched: true)" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=trace msg="scheduling prefetch in 133s" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=trace msg="emitting websocket event: metadata" Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=trace msg="emitting websocket event: playing" Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ebca7d93f21ba366fe005966","album_name":"Damn The Torpedoes (Deluxe Edition)","artist_names":["Tom Petty and the Heartbreakers"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":161786,"format":"OGG_VORBIS_320","name":"Don't Do Me Like That","position":0,"release_date":"year:1979 month:10 day:19","sample_rate":44100,"track_number":6,"uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf"}} Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:4mcZYzoGwPRDdhWVlygiHf","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","resume":false,"play_origin":"go-librespot"}} Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: PUSH STATE SPOTIFY Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: {"status":"play","service":"spop","title":"Don't Do Me Like That","artist":"Tom Petty and the Heartbreakers","album":"Damn The Torpedoes (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02ebca7d93f21ba366fe005966","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","trackType":"spotify","seek":0,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::servicePushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Don't Do Me Like That","artist":"Tom Petty and the Heartbreakers","album":"Damn The Torpedoes (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02ebca7d93f21ba366fe005966","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","trackType":"spotify","seek":0,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 13 20:31:08 rivoplus volumio[3585]: verbose: CURRENT POSITION 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::syncState stateService play Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::syncState currentStatus play Oct 13 20:31:08 rivoplus volumio[3585]: info: Received an update from plugin. extracting info from payload Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::pushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioPushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output update for this device Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::pushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioPushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output update for this device Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.621+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" state=STATUS_PLAYING positionMs=199564 volume=55 Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.622+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" id=spotify:track:4mcZYzoGwPRDdhWVlygiHf title=Refugee Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.630+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" state=STATUS_PLAYING positionMs=199564 volume=55 Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.631+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" id=spotify:track:4mcZYzoGwPRDdhWVlygiHf title=Refugee Oct 13 20:31:08 rivoplus volumio[3585]: info: Signalling Playback active due to playback status change Oct 13 20:31:08 rivoplus volumio[3585]: info: Signalling Playback active due to playback status change Oct 13 20:31:08 rivoplus volumio[3585]: info: Updating RAAT Signal Path Oct 13 20:31:08 rivoplus volumio[3585]: info: Updating RAAT Signal Path Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 13 20:31:08 rivoplus go-librespot[4930]: time="2026-10-13T20:31:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: PUSH STATE SPOTIFY Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: {"status":"play","service":"spop","title":"Don't Do Me Like That","artist":"Tom Petty and the Heartbreakers","album":"Damn The Torpedoes (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02ebca7d93f21ba366fe005966","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","trackType":"spotify","seek":1000,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::servicePushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Don't Do Me Like That","artist":"Tom Petty and the Heartbreakers","album":"Damn The Torpedoes (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02ebca7d93f21ba366fe005966","uri":"spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf","trackType":"spotify","seek":1000,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 13 20:31:08 rivoplus volumio[3585]: verbose: CURRENT POSITION 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::syncState stateService play Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::syncState currentStatus play Oct 13 20:31:08 rivoplus volumio[3585]: info: Received an update from plugin. extracting info from payload Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::pushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioPushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output update for this device Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreStateMachine::pushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioPushState Oct 13 20:31:08 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:08 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 0 Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output update for this device Oct 13 20:31:08 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.922+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" state=STATUS_PLAYING positionMs=199814 volume=55 Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.922+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" id=spotify:track:4mcZYzoGwPRDdhWVlygiHf title=Refugee Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.924+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" state=STATUS_PLAYING positionMs=199814 volume=55 Oct 13 20:31:08 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:08.924+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" id=spotify:track:4mcZYzoGwPRDdhWVlygiHf title=Refugee Oct 13 20:31:08 rivoplus volumio[3585]: info: Signalling Playback active due to playback status change Oct 13 20:31:08 rivoplus volumio[3585]: info: Signalling Playback active due to playback status change Oct 13 20:31:08 rivoplus volumio[3585]: info: Updating RAAT Signal Path Oct 13 20:31:08 rivoplus volumio[3585]: info: Updating RAAT Signal Path Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 13 20:31:08 rivoplus volumio[3585]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 13 20:31:09 rivoplus volumio[3585]: info: CoreStateMachine::startPlaybackTimer Oct 13 20:31:09 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:09 rivoplus volumio[3585]: info: CoreStateMachine::pushState Oct 13 20:31:09 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:09 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 20:31:09 rivoplus volumio[3585]: info: CoreCommandRouter::volumioPushState Oct 13 20:31:09 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:09 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:09 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output update for this device Oct 13 20:31:09 rivoplus volumio[3585]: info: MRS: Pushing multiroomSync output Oct 13 20:31:10 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:10.000+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" state=STATUS_PLAYING positionMs=250 volume=55 Oct 13 20:31:10 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:10.001+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" id=spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf title="Don't Do Me Like That" Oct 13 20:31:10 rivoplus volumio[3585]: info: Signalling Playback active due to playback status change Oct 13 20:31:10 rivoplus volumio[3585]: info: Updating RAAT Signal Path Oct 13 20:31:10 rivoplus volumio[3585]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 13 20:31:20 rivoplus go-librespot[4930]: time="2026-10-13T20:31:20+02:00" level=debug msg="fetched chunk 4/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:33 rivoplus go-librespot[4930]: time="2026-10-13T20:31:33+02:00" level=debug msg="fetched chunk 5/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:37 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:37.695+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s Oct 13 20:31:37 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:37.823+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=http://pushupdates.volumio.org duration=122.836878ms Oct 13 20:31:37 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:37.949+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=253.555031ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.026+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://www.googleapis.com duration=326.859131ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.107+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://securetoken.googleapis.com duration=410.831973ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.183+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://functions.volumio.cloud duration=482.647569ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.183+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://functions.volumio.cloud duration=484.676908ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.194+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=496.22107ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.210+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=512.470369ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.221+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=525.015783ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.600+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://database.volumio.cloud duration=901.168359ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.608+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=http://plugins.volumio.org duration=910.264053ms Oct 13 20:31:38 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:38.721+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=https://google.com duration=1.023739902s Oct 13 20:31:38 rivoplus volumio[3585]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.239 UA: Mozilla/5.0 (Linux; Android 15; ASUS_AI2302 Build/AQ3A.240812.002; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/153.0.8010.36 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 9 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 20:31:38 rivoplus volumio[3585]: info: Discovery: Getting this device information Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:38 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 20:31:38 rivoplus volumio[3585]: verbose: New Socket.io Connection to 192.168.1.39:3000 from 192.168.1.239 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetVisibleSources Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:38 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetQueue Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreStateMachine::getQueue Oct 13 20:31:38 rivoplus volumio[3585]: info: CorePlayQueue::getQueue Oct 13 20:31:38 rivoplus volumio[3585]: info: Listing playlists Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 13 20:31:38 rivoplus volumio[3585]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 13 20:31:38 rivoplus volumio[3585]: info: Received Get System Info Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 20:31:38 rivoplus volumio[3585]: info: Discovery: Getting this device information Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:38 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::volumioGetState Oct 13 20:31:38 rivoplus volumio[3585]: info: CorePlayQueue::getTrack 1 Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 13 20:31:38 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 13 20:31:39 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 13 20:31:39 rivoplus volumio5-onboarding[4687]: time=2026-10-13T20:31:39.476+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.239:42932,00:00:00:00:00:00%02 @ 0x3078270" latency=-7.419258707s timeout=10s endpoint=http://cddb.volumio.org duration=1.777459768s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 13 20:31:46 rivoplus go-librespot[4930]: time="2026-10-13T20:31:46+02:00" level=debug msg="fetched chunk 6/12, size: 524288" uri="spotify:track:5AzpZ5ADn1AFPxcEBd2Ugf" Oct 13 20:31:49 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 13 20:31:49 rivoplus volumio[3585]: info: CURURI: music-library Oct 13 20:31:49 rivoplus volumio[3585]: error: Failed LSINFO: null Oct 13 20:31:49 rivoplus volumio[3585]: info: Preload queue cleared Oct 13 20:31:57 rivoplus volumio[3585]: info: CoreCommandRouter::executeOnPlugin: last_100 , handleBrowseUri Oct 13 20:31:57 rivoplus volumio[3585]: info: Preload queue cleared Oct 13 20:31:57 rivoplus volumio[3585]: info: Preloading song: http://stream.radioparadise.com/beyond-flacm Oct 13 20:31:57 rivoplus volumio[3585]: info: Preloading song: https://stream.radioparadise.com/mellow-flacm Oct 13 20:31:57 rivoplus volumio[3585]: info: Exploding uri http://stream.radioparadise.com/beyond-flacm in service radio_paradise Oct 13 20:31:57 rivoplus volumio[3585]: error: [RadioParadise] explodeUri: No station found for uri "http://stream.radioparadise.com/beyond-flacm" Oct 13 20:31:57 rivoplus volumio[3585]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 20:31:57 rivoplus volumio[3585]: TypeError: Cannot read properties of undefined (reading 'then') Oct 13 20:31:57 rivoplus volumio[3585]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1384:31) Oct 13 20:31:57 rivoplus volumio[3585]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Oct 13 20:31:57 rivoplus volumio[3585]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Oct 13 20:31:57 rivoplus volumio[3585]: at Timeout._onTimeout (/volumio/app/playqueue.js:146:100) Oct 13 20:31:57 rivoplus volumio[3585]: at listOnTimeout (node:internal/timers:573:17) Oct 13 20:31:57 rivoplus volumio[3585]: at process.processTimers (node:internal/timers:514:7) Oct 13 20:31:57 rivoplus volumio[3585]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 20:31:58 rivoplus sudo[9818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-13 20:30' Oct 13 20:31:58 rivoplus sudo[9818]: 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="8ed05bf20f96eb8557ed5652c420f84f39d66325" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0a52c1fb90959ba1872a2fb0225e56fe615b19ac" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Sep 16 16:52:40 UTC 2026" VOLUMIO_VERSION="4.208" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="ba37532a86808e19439a6278b2d45f47"