Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.261+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.285+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=22.845759ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.286+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=24.148815ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.293+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=http://pushupdates.volumio.org duration=31.346537ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.298+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=36.763222ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.370+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://www.googleapis.com duration=108.524093ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.399+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=136.805074ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.401+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://functions.volumio.cloud duration=139.840462ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.403+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://securetoken.googleapis.com duration=141.433037ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.405+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://functions.volumio.cloud duration=142.928037ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.412+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://database.volumio.cloud duration=149.595629ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.598+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=https://google.com duration=336.929778ms Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.715+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=http://cddb.volumio.org duration=453.127888ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 02 12:12:05 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:05.798+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-610.154946ms timeout=10s endpoint=http://plugins.volumio.org duration=536.094333ms Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:06 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:06 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:06 volumio volumio[1194]: verbose: New Socket.io Connection to 192.168.0.180:3000 from 192.168.0.108 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 12:12:06 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.283+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-624.073447ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.302+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.329+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=22.595352ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.329+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=23.353278ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.340+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=33.724889ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.340+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=http://pushupdates.volumio.org duration=34.101889ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.417+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://www.googleapis.com duration=111.577204ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.439+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=133.389888ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.445+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://securetoken.googleapis.com duration=139.00687ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.450+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://database.volumio.cloud duration=143.990037ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.453+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://functions.volumio.cloud duration=146.994278ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.454+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://functions.volumio.cloud duration=147.745407ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.566+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=http://cddb.volumio.org duration=259.828629ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.652+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=http://plugins.volumio.org duration=345.791148ms Oct 02 12:12:07 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:07.664+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" latency=-623.874373ms timeout=10s endpoint=https://google.com duration=358.162648ms Oct 02 12:12:07 volumio sudo[1950]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 12:12:07 volumio sudo[1950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:07 volumio sudo[1952]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 12:12:08 volumio sudo[1952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:08 volumio sudo[1950]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:08 volumio sudo[1952]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:08 volumio volumio[1194]: verbose: New Socket.io Connection to 192.168.0.180 from 192.168.0.108 UA: Mozilla/5.0 (Linux; Android 16; 2407FPN8EG Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/153.0.8010.36 Mobile Safari/537.36 VolumioApp/6.260915.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::volumioGetVisibleSources Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:08 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 02 12:12:08 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:08 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:08 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:08 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:08 volumio volumio[1194]: info: Listing playlists Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 02 12:12:08 volumio sudo[1957]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 12:12:08 volumio sudo[1957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:08 volumio sudo[1957]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:08 volumio sudo[1959]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 12:12:08 volumio sudo[1959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:08 volumio sudo[1959]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:08 volumio volumio[1194]: verbose: New Socket.io Connection to 192.168.0.180 from 192.168.0.108 UA: Mozilla/5.0 (Linux; Android 16; 2407FPN8EG Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/153.0.8010.36 Mobile Safari/537.36 VolumioApp/6.260915.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 02 12:12:08 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::volumioGetVisibleSources Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:09 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 02 12:12:09 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:09 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:09 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:09 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:09 volumio volumio[1194]: info: Listing playlists Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 02 12:12:09 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 12:12:10 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:10 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:10 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:10 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 02 12:12:14 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 12:12:16 volumio sudo[1964]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 12:12:16 volumio sudo[1964]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:16 volumio sudo[1964]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:16 volumio sudo[1966]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 12:12:16 volumio sudo[1966]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:16 volumio sudo[1966]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:17 volumio volumio[1194]: verbose: New Socket.io Connection to 192.168.0.180 from 192.168.0.108 UA: Mozilla/5.0 (Linux; Android 16; 2407FPN8EG Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/153.0.8010.36 Mobile Safari/537.36 VolumioApp/6.260915.0 Engine version: 3 Transport: polling Total Clients: 6 Oct 02 12:12:17 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:17 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:17 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:17 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetVisibleSources Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:17 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 02 12:12:17 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:17 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:17 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:17 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:17 volumio volumio[1194]: info: Listing playlists Oct 02 12:12:17 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 02 12:12:18 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 02 12:12:26 volumio volumio[1194]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 02 12:12:26 volumio volumio[1194]: info: Received Get System Version Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 02 12:12:26 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:26 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:26 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:26 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:27 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 02 12:12:32 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 02 12:12:32 volumio volumio[1194]: info: MyVolumio login type: Token Oct 02 12:12:32 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 12:12:32 volumio volumio5-onboarding[1465]: time=2026-10-02T12:12:32.195+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.108:35754,00:00:00:00:00:00%01 @ 0x2f58090" userId= Oct 02 12:12:32 volumio volumio[1194]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 02 12:12:33 volumio volumio[1194]: info: MyVolumio token set successfully Oct 02 12:12:33 volumio volumio[1194]: info: MYVOLUMIO: Adding device Oct 02 12:12:33 volumio volumio[1194]: info: MYVOLUMIO: Evaluating Server Oct 02 12:12:34 volumio volumio[1194]: info: MyVolumio status changed Oct 02 12:12:34 volumio volumio[1194]: info: Streaming services startup Oct 02 12:12:34 volumio volumio[1194]: info: Starting Streaming Daemon Oct 02 12:12:34 volumio volumio[1194]: info: Removing browser output: myVolumio user plan is not superstar Oct 02 12:12:34 volumio volumio[1194]: info: Removing audio output: Oct 02 12:12:34 volumio volumio[1194]: info: Stoppping Tunnel 1 Oct 02 12:12:34 volumio sudo[2021]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 02 12:12:34 volumio sudo[2021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:34 volumio sudo[2023]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 02 12:12:34 volumio sudo[2023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:34 volumio sudo[2021]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio volumio[1194]: error: Cannot start Volumio Streaming Daemon Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio volumio[1194]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 02 12:12:34 volumio volumio[1194]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:12:34 volumio sudo[2023]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:34 volumio volumio[1194]: info: Remote SSH Stopped Oct 02 12:12:34 volumio volumio[1194]: info: Setting Geolocation for MyVolumio to eu6 Oct 02 12:12:34 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:34 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:34 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:34 volumio volumio[1194]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 02 12:12:35 volumio volumio[1194]: info: Updating MyVolumio device info Oct 02 12:12:35 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:35 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:35 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:35 volumio volumio[1194]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 02 12:12:38 volumio volumio[1194]: info: MYVOLUMIO: Adding device Oct 02 12:12:38 volumio volumio[1194]: info: MYVOLUMIO: Evaluating Server Oct 02 12:12:39 volumio sudo[2059]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 12:12:39 volumio sudo[2061]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 12:12:39 volumio sudo[2061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:39 volumio sudo[2059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:12:39 volumio sudo[2061]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:39 volumio sudo[2059]: pam_unix(sudo:session): session closed for user root Oct 02 12:12:39 volumio volumio[1194]: info: Setting Geolocation for MyVolumio to eu4 Oct 02 12:12:39 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:39 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:39 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:39 volumio volumio[1194]: verbose: New Socket.io Connection to 192.168.0.180 from 192.168.0.108 UA: Mozilla/5.0 (Linux; Android 16; 2407FPN8EG Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/153.0.8010.36 Mobile Safari/537.36 VolumioApp/6.260915.0 Engine version: 3 Transport: polling Total Clients: 6 Oct 02 12:12:39 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:40 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetVisibleSources Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 02 12:12:40 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:40 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: Listing playlists Oct 02 12:12:40 volumio volumio[1194]: info: Received Get System Info Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 12:12:40 volumio volumio[1194]: info: Discovery: Getting this device information Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:12:40 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:12:40 volumio volumio[1194]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 02 12:12:40 volumio volumio[1194]: info: Updating MyVolumio device info Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 12:12:40 volumio volumio[1194]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 02 12:12:41 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 12:12:41 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 02 12:12:49 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 02 12:13:08 volumio volumio[1194]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Oct 02 12:13:08 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:08.162+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:10 volumio volumio[1194]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Oct 02 12:13:10 volumio volumio[1194]: info: Folder /tmp/plugins removed Oct 02 12:13:10 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:10.444+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:13 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:13.196+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:13 volumio volumio[1194]: info: Check plugin dependencies Oct 02 12:13:13 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 02 12:13:13 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:13.562+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:13 volumio volumio[1194]: info: Checking if plugin already exists Oct 02 12:13:13 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:13.594+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:13 volumio volumio[1194]: info: Rename folder Oct 02 12:13:13 volumio volumio[1194]: info: Folder /tmp/downloaded_plugin.zip removed Oct 02 12:13:13 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:13.745+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:13 volumio volumio[1194]: info: Move to category Oct 02 12:13:15 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:15.319+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:15 volumio volumio[1194]: info: Checking if install.sh is present Oct 02 12:13:15 volumio volumio[1194]: info: Executing install.sh Oct 02 12:13:15 volumio sudo[2127]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Oct 02 12:13:15 volumio sudo[2127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:13:15 volumio volumio[1194]: info: Installing Go-librespot Oct 02 12:13:15 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:15.825+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:15 volumio volumio[1194]: info: Checking old vollibrespot installs Oct 02 12:13:15 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:15.938+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:15 volumio systemd[1]: Reloading. Oct 02 12:13:17 volumio volumio[1194]: info: Downloading daemon Oct 02 12:13:17 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:17.104+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:21 volumio volumio[1194]: info: Creating directories Oct 02 12:13:21 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:21.747+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:21 volumio volumio[1194]: info: Creating data directory Oct 02 12:13:21 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:21.783+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:21 volumio volumio[1194]: info: Creating Start Script Oct 02 12:13:21 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:21.848+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:21 volumio systemd[1]: Reloading. Oct 02 12:13:23 volumio sudo[2127]: pam_unix(sudo:session): session closed for user root Oct 02 12:13:23 volumio volumio[1194]: Plugin install end detected on script Oct 02 12:13:23 volumio volumio[1194]: info: Install script completed Oct 02 12:13:23 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:23.086+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:23 volumio volumio[1194]: info: Adding reference to registry Oct 02 12:13:23 volumio volumio5-onboarding[1465]: time=2026-10-02T12:13:23.103+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Oct 02 12:13:23 volumio volumio[1194]: info: Done installing plugin. Oct 02 12:13:23 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 12:13:23 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 02 12:13:23 volumio volumio[1194]: info: Folder /tmp/plugins removed Oct 02 12:13:23 volumio volumio[1194]: info: Folder /tmp/downloaded_plugin.zip removed Oct 02 12:13:23 volumio volumio[1194]: info: Folder /data/temp removed Oct 02 12:13:36 volumio volumio[1194]: info: Enabling plugin spop Oct 02 12:13:36 volumio volumio[1194]: info: Loading plugin "spop"... Oct 02 12:13:40 volumio volumio[1194]: info: PLUGIN START: spop Oct 02 12:13:40 volumio volumio[1194]: info: Creating Spotify config file Oct 02 12:13:40 volumio volumio[1194]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 12:13:40 volumio volumio[1194]: info: Done. Oct 02 12:13:40 volumio volumio[1194]: info: Spotify config file written Oct 02 12:13:40 volumio sudo[2227]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 02 12:13:40 volumio sudo[2227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 12:13:41 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:13:41 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 02 12:13:41 volumio volumio[1194]: info: No need to fix Spotify hosts Oct 02 12:13:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 02 12:13:41 volumio go-librespot[2229]: go-librespot daemon starting... Oct 02 12:13:41 volumio sudo[2227]: pam_unix(sudo:session): session closed for user root Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=info msg="running go-librespot 0.9.1" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=debug msg="no app state found" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=debug msg="stored credentials not found" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=info msg="generated new device id: f570c900c253bd976e86fd6fc276478acfea51e1" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+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-gew1.spotify.com:80]" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=info msg="zeroconf server listening on port 40375" Oct 02 12:13:41 volumio go-librespot[2230]: time="2026-10-02T12:13:41+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 02 12:13:42 volumio go-librespot[2230]: time="2026-10-02T12:13:42+02:00" level=debug msg="avahi service \"Volumio\" established" Oct 02 12:13:44 volumio volumio[1194]: info: go-librespot daemon successfully initialized Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="obtained new client token: AAG8fgDd3tzhAL37L0zduFwMyo/ZVxJcjhp18LdELoJCiCRhQ10UOD4QDvXfYpJyIl2Q+fNxxfaXxiOqMHIUfgwIZM6+7eZHZYZKeRjzOOWrS3wC6wZIhgt17IDEuBxjt4nV/koE+XZOo55wHlDCwGN9lpvJiSD88gibdtjKdwHxaXhKYoOR81vn26LBvwMPt7VfoAWC72uinGCPMTH54BrNWSbC8wYFSaIV8X4VxbndjDwMSUYg8UGp" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="completed keyexchange" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="completed challenge" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=info msg="authenticated AP" username="fa******sd" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=info msg="authenticated Login5" username="fa******sd" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="persisted zeroconf credentials" username="fa******sd" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=info msg="accepted zeroconf from Xiaomi 14T Pro" username="fa******sd" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="connected to gew4-dealer.spotify.com:443" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=trace msg="starting accesspoint recv loop" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=trace msg="starting dealer recv loop" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="received connection id: YzBjY2FiYmEtZThh...QzlDQ0I3RjQ1Rg==" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 02 12:13:46 volumio go-librespot[2230]: time="2026-10-02T12:13:46+02:00" level=trace msg="emitting websocket event: playback_ready" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="handling transfer player command from 600a499a1ced138b29d7e364e955d5859c8547ac" Oct 02 12:13:47 volumio volumio[1194]: info: Initializing connection to go-librespot Websocket Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="new websocket client" Oct 02 12:13:47 volumio volumio[1194]: info: Connection to go-librespot Websocket established Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:0KlX2BJPiXm0BePr90DDPl" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="fetched new page 0 with 2427 items (list: 2427)" uri="spotify:playlist:0KlX2BJPiXm0BePr90DDPl" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="loading track (paused: false, position: 164343ms)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="emitting websocket event: will_play" Oct 02 12:13:47 volumio volumio[1194]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:0KlX2BJPiXm0BePr90DDPl","uri":"spotify:track:1Th7EFFIHB4MKrF3NsIsVz","play_origin":"playlist"}} Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="selected format OGG_VORBIS_320 (b4d9a8f7b53171d801b123999e460f966ce2d657)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="requested aes key for file b4d9a8f7b53171d801b123999e460f966ce2d657, gid: 1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="fetched first chunk of 11, total size is 5287922 bytes" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1524" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="fetched chunk 10/10, size: 45042" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="seek to 139285ms (diff: 109ms, samples: 6142468, bytes: 5275399)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="track has no narration" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="created new output device" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=info msg="loaded track \"DOING THIS FOR ME\" (paused: false, position: 164343ms, duration: 139285ms, prefetched: false)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="prefetch as soon as possible" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="emitting websocket event: metadata" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="emitting websocket event: active" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="sending successful reply for dealer request" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=trace msg="emitting websocket event: playing" Oct 02 12:13:47 volumio volumio[1194]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e027e3c8463cac773f73d0f7058","album_name":"DOING THIS FOR ME (SLOWED \u0026 SPED UP)","artist_names":["bystander","emerge"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":139285,"format":"OGG_VORBIS_320","name":"DOING THIS FOR ME","position":164343,"release_date":"year:2026 month:7 day:17","sample_rate":44100,"track_number":3,"uri":"spotify:track:1Th7EFFIHB4MKrF3NsIsVz"}} Oct 02 12:13:47 volumio volumio[1194]: SPOTIFY: received: {"type":"active","data":null} Oct 02 12:13:47 volumio volumio[1194]: info: Aligning Spotify Volume to Volumio Volume Oct 02 12:13:47 volumio volumio[1194]: info: CoreCommandRouter::volumioGetState Oct 02 12:13:47 volumio volumio[1194]: info: CorePlayQueue::getTrack 0 Oct 02 12:13:47 volumio volumio[1194]: info: Setting Spotify Volume from Volumio: 20 Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 02 12:13:47 volumio volumio[1194]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:0KlX2BJPiXm0BePr90DDPl","uri":"spotify:track:1Th7EFFIHB4MKrF3NsIsVz","resume":false,"play_origin":"playlist"}} Oct 02 12:13:47 volumio volumio[1194]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 12:13:47 volumio volumio[1194]: TypeError: Cannot read properties of undefined (reading 'service') Oct 02 12:13:47 volumio volumio[1194]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:358:50) Oct 02 12:13:47 volumio volumio[1194]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:284:18) Oct 02 12:13:47 volumio volumio[1194]: at WebSocket.message (/data/plugins/music_service/spop/index.js:208:14) Oct 02 12:13:47 volumio volumio[1194]: at WebSocket.emit (node:events:514:28) Oct 02 12:13:47 volumio volumio[1194]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 02 12:13:47 volumio volumio[1194]: at Receiver.emit (node:events:514:28) Oct 02 12:13:47 volumio volumio[1194]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 02 12:13:47 volumio volumio[1194]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 02 12:13:47 volumio volumio[1194]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 02 12:13:47 volumio volumio[1194]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 02 12:13:47 volumio volumio[1194]: at writeOrBuffer (node:internal/streams/writable:399:12) Oct 02 12:13:47 volumio volumio[1194]: at _write (node:internal/streams/writable:340:10) Oct 02 12:13:47 volumio volumio[1194]: at Writable.write (node:internal/streams/writable:344:10) Oct 02 12:13:47 volumio volumio[1194]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 02 12:13:47 volumio volumio[1194]: at Socket.emit (node:events:514:28) Oct 02 12:13:47 volumio volumio[1194]: at addChunk (node:internal/streams/readable:343:12) Oct 02 12:13:47 volumio volumio[1194]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="prefetching next track" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1275" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="selected format OGG_VORBIS_320 (b4d9a8f7b53171d801b123999e460f966ce2d657)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:47 volumio go-librespot[2230]: time="2026-10-02T12:13:47+02:00" level=debug msg="requested aes key for file b4d9a8f7b53171d801b123999e460f966ce2d657, gid: 1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="fetched first chunk of 11, total size is 5287922 bytes" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=info msg="prefetched track \"DOING THIS FOR ME\" (duration: 139285ms)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="emitting websocket event: not_playing" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="emitting websocket event: will_play" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="track has no narration" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=info msg="loaded track \"DOING THIS FOR ME\" (paused: false, position: 0ms, duration: 139285ms, prefetched: true)" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="scheduling prefetch in 109s" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="emitting websocket event: metadata" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=trace msg="emitting websocket event: playing" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:1Th7EFFIHB4MKrF3NsIsVz" Oct 02 12:13:48 volumio go-librespot[2230]: time="2026-10-02T12:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 12:13:51 volumio sudo[2270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-02 12:12' Oct 02 12:13:51 volumio sudo[2270]: 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"