Aug 30 18:33:01 primo-plus volumio[1092]: info: VolumeController::SetAlsaVolume100 Aug 30 18:33:01 primo-plus volumio[1092]: info: CoreStateMachine::pushState Aug 30 18:33:01 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:01 primo-plus volumio[1092]: info: CoreCommandRouter::volumioPushState Aug 30 18:33:01 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:01 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:01 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:01.569+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" state=STATUS_STOPPED positionMs=0 volume=100 Aug 30 18:33:01 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:01.570+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" id= title= Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.622+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=5.708041ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.657+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.672+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=14.68523ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.745+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=80.044472ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.748+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=83.05771ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.768+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://google.com duration=104.013525ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.776+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://www.googleapis.com duration=112.307874ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.829+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=171.082811ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.841+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://database.volumio.cloud duration=176.247997ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.843+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://functions.volumio.cloud duration=177.820172ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.860+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://functions.volumio.cloud duration=196.507428ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.880+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=https://securetoken.googleapis.com duration=222.440115ms Aug 30 18:33:03 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:03.936+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=http://pushupdates.volumio.org duration=278.516738ms Aug 30 18:33:04 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:04.466+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=http://plugins.volumio.org duration=802.502374ms Aug 30 18:33:04 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:04.468+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=13.418936ms timeout=10s endpoint=http://cddb.volumio.org duration=810.153839ms Aug 30 18:33:04 primo-plus sudo[2576]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 18:33:04 primo-plus sudo[2576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:04 primo-plus sudo[2576]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:04 primo-plus sudo[2578]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 18:33:04 primo-plus sudo[2578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:04 primo-plus sudo[2578]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:04 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 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: 9 Aug 30 18:33:04 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 30 18:33:05 primo-plus sudo[2582]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 18:33:05 primo-plus sudo[2582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:05 primo-plus sudo[2582]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:05 primo-plus sudo[2584]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 18:33:05 primo-plus sudo[2584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:05 primo-plus sudo[2584]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:05 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 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: 9 Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetVisibleSources Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:05 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 30 18:33:05 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:05 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:05 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:05 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:05 primo-plus volumio[1092]: info: Listing playlists Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 18:33:05 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 30 18:33:06 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 30 18:33:07 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:07 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:07 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:07 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:07 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:07 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:07 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:07 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:08 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:08 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:08 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:08 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:08 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:08 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:08 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:08 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:11 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 8. Aug 30 18:33:11 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:11 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 30 18:33:11 primo-plus upmpdcli[2603]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:33:11 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:33:11 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Aug 30 18:33:11 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Aug 30 18:33:12 primo-plus volumio[1092]: info: Received Get System Version Aug 30 18:33:12 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 18:33:15 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 30 18:33:23 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:23.818+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=6.481249ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 30 18:33:23 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:23.909+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s Aug 30 18:33:23 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:23.918+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=8.784587ms Aug 30 18:33:23 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:23.991+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=80.959706ms Aug 30 18:33:23 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:23.995+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=84.978734ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.015+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://google.com duration=104.403985ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.019+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://www.googleapis.com duration=108.454142ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.075+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=163.127682ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.086+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://database.volumio.cloud duration=173.743145ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.087+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://functions.volumio.cloud duration=174.926859ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.090+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://functions.volumio.cloud duration=178.625517ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.132+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=https://securetoken.googleapis.com duration=221.17655ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.185+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=http://pushupdates.volumio.org duration=273.717235ms Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 18:33:24 primo-plus volumio[1092]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 30 18:33:24 primo-plus volumio[1092]: info: Received Get System Version Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 18:33:24 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:24 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:24 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:24 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.451+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=http://plugins.volumio.org duration=539.251676ms Aug 30 18:33:24 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:33:24.709+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=67.525513ms timeout=10s endpoint=http://cddb.volumio.org duration=798.245402ms Aug 30 18:33:24 primo-plus sudo[2637]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 18:33:24 primo-plus sudo[2637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:24 primo-plus sudo[2639]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 18:33:24 primo-plus sudo[2637]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:24 primo-plus sudo[2639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:24 primo-plus sudo[2639]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:24 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 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: 10 Aug 30 18:33:25 primo-plus sudo[2643]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 18:33:25 primo-plus sudo[2643]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:25 primo-plus sudo[2643]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:25 primo-plus sudo[2645]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 18:33:25 primo-plus sudo[2645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:25 primo-plus sudo[2645]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:25 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 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: 10 Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetVisibleSources Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:25 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 30 18:33:25 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:25 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:25 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:25 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:25 primo-plus volumio[1092]: info: Listing playlists Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 18:33:25 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 30 18:33:26 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 30 18:33:26 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 9. Aug 30 18:33:26 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:26 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:26 primo-plus upmpdcli[2649]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:33:26 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:33:26 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:33:27 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:27 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:27 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:27 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:27 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:27 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:27 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:27 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:28 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:28 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:28 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:28 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:28 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:28 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:28 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:28 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:30 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:30 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 30 18:33:33 primo-plus volumio[1092]: info: Enabling plugin spop Aug 30 18:33:33 primo-plus volumio[1092]: info: Loading plugin "spop"... Aug 30 18:33:34 primo-plus volumio[1092]: info: PLUGIN START: spop Aug 30 18:33:34 primo-plus volumio[1092]: info: Creating Spotify config file Aug 30 18:33:34 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 18:33:34 primo-plus volumio[1092]: info: Done. Aug 30 18:33:34 primo-plus volumio[1092]: info: Spotify config file written Aug 30 18:33:34 primo-plus volumio[1092]: info: No need to fix Spotify hosts Aug 30 18:33:34 primo-plus sudo[2665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 30 18:33:34 primo-plus sudo[2665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:33:34 primo-plus 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. Aug 30 18:33:34 primo-plus 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. Aug 30 18:33:34 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:33:34 primo-plus go-librespot[2667]: go-librespot daemon starting... Aug 30 18:33:34 primo-plus sudo[2665]: pam_unix(sudo:session): session closed for user root Aug 30 18:33:35 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=info msg="running go-librespot 0.7.1" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=debug msg="app state loaded" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=debug msg="stored credentials not found" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=info msg="zeroconf server listening on port 38011" Aug 30 18:33:35 primo-plus go-librespot[2668]: time="2026-08-30T18:33:35+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 18:33:37 primo-plus volumio[1092]: info: go-librespot daemon successfully initialized Aug 30 18:33:40 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:33:40 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 30 18:33:40 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:33:40 primo-plus go-librespot[2668]: time="2026-08-30T18:33:40+09:00" level=debug msg="new websocket client" Aug 30 18:33:40 primo-plus volumio[1092]: info: Connection to go-librespot Websocket established Aug 30 18:33:42 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 10. Aug 30 18:33:42 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:42 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:42 primo-plus upmpdcli[2693]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:33:42 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:33:42 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:33:42 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 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: 10 Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetVisibleSources Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:42 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 30 18:33:42 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:42 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:42 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:42 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:42 primo-plus volumio[1092]: info: Listing playlists Aug 30 18:33:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 18:33:43 primo-plus volumio[1092]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 30 18:33:43 primo-plus volumio[1092]: info: Received Get System Version Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 18:33:43 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:33:43 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:43 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:33:44 primo-plus volumio[1092]: info: Getting Spotify volume Aug 30 18:33:44 primo-plus volumio[1092]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Aug 30 18:33:44 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:33:44 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:33:45 primo-plus volumio[1092]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 30 18:33:57 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 11. Aug 30 18:33:57 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:57 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:33:57 primo-plus upmpdcli[2711]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:33:57 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:33:57 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.340+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.348+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=8.192453ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.423+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=82.023974ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.425+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=83.617887ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.453+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://www.googleapis.com duration=112.398527ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.478+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://google.com duration=137.571548ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.484+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.104.219:53403 Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.507+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=166.372059ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.517+09:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.104.219:53403 Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.518+09:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.104.219:53403 Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.519+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://functions.volumio.cloud duration=176.741254ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.519+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://functions.volumio.cloud duration=177.508747ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.561+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://securetoken.googleapis.com duration=220.513514ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.618+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=http://pushupdates.volumio.org duration=275.322373ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.831+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=http://plugins.volumio.org duration=489.232829ms Aug 30 18:34:11 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:11.838+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=https://database.volumio.cloud duration=495.706851ms Aug 30 18:34:12 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:12.128+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=11.828591ms timeout=10s endpoint=http://cddb.volumio.org duration=787.149985ms Aug 30 18:34:12 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:12.530+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.104.219:53407 Aug 30 18:34:12 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:12.567+09:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.104.219:53407 Aug 30 18:34:12 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:12.567+09:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.104.219:53407 Aug 30 18:34:12 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 12. Aug 30 18:34:12 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:12 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:12 primo-plus upmpdcli[2741]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:34:12 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:12 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:34:13 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:13 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:34:13 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148:3000 from 192.168.104.219 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 18:34:13 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 18:34:14 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:14.666+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.104.219:53513 Aug 30 18:34:14 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:14.693+09:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.104.219:53513 Aug 30 18:34:14 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:14.694+09:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.104.219:53513 Aug 30 18:34:27 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 13. Aug 30 18:34:27 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:27 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:27 primo-plus upmpdcli[2756]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:34:27 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:27 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.760+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.771+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=10.835636ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.842+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=80.606917ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.849+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=87.667972ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.866+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://google.com duration=105.209629ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.871+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://www.googleapis.com duration=109.799833ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.926+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=165.13221ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.937+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://database.volumio.cloud duration=174.636319ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.940+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://functions.volumio.cloud duration=178.108607ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.940+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://functions.volumio.cloud duration=177.656814ms Aug 30 18:34:30 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:30.986+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=https://securetoken.googleapis.com duration=223.876707ms Aug 30 18:34:31 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:31.036+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=http://pushupdates.volumio.org duration=273.628368ms Aug 30 18:34:31 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:31.318+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=http://plugins.volumio.org duration=556.389682ms Aug 30 18:34:31 primo-plus volumio5-onboarding[2145]: time=2026-08-30T18:34:31.566+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.104.219:53215,00:00:00:00:00:00%01 @ 0x1edd650" latency=20.527485ms timeout=10s endpoint=http://cddb.volumio.org duration=804.657086ms Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:34:33 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:33 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:34:33 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148:3000 from 192.168.104.219 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 18:34:33 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 18:34:40 primo-plus volumio[1092]: info: Received OAUTH Data Aug 30 18:34:40 primo-plus volumio[1092]: info: Executing Spotify Oauth Login Aug 30 18:34:40 primo-plus volumio[1092]: info: Saving Spotify Refresh Token Aug 30 18:34:40 primo-plus volumio[1092]: info: New Spotify access tokenBQCivQDO82... Aug 30 18:34:40 primo-plus volumio[1092]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 30 18:34:40 primo-plus volumio[1092]: SPOTIFY: User informations: {"account_id":"qtI6EIubwV","country":"JP","display_name":"Akinori Ito","email":"akinori0110@yahoo.co.jp","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31ilqejszxg23iz5olx4nv4ucjdm"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31ilqejszxg23iz5olx4nv4ucjdm","id":"31ilqejszxg23iz5olx4nv4ucjdm","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85e8846bb82d3424f2ad6a07ac","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82e8846bb82d3424f2ad6a07ac","width":64}],"product":"premium","type":"user","uri":"spotify:user:31ilqejszxg23iz5olx4nv4ucjdm"} Aug 30 18:34:40 primo-plus volumio[1092]: info: Creating Spotify config file Aug 30 18:34:40 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 18:34:40 primo-plus volumio[1092]: info: Spotify config file written Aug 30 18:34:40 primo-plus sudo[2788]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 30 18:34:40 primo-plus sudo[2788]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:34:40 primo-plus systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 30 18:34:40 primo-plus sudo[2791]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 18:34:40 primo-plus sudo[2791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:34:40 primo-plus systemd[1]: go-librespot-daemon.service: Killing process 2672 (go-librespot) with signal SIGKILL. Aug 30 18:34:40 primo-plus systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 30 18:34:40 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:40 primo-plus sudo[2791]: pam_unix(sudo:session): session closed for user root Aug 30 18:34:40 primo-plus sudo[2793]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 18:34:40 primo-plus sudo[2793]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 18:34:40 primo-plus sudo[2793]: pam_unix(sudo:session): session closed for user root Aug 30 18:34:40 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:40 primo-plus go-librespot[2795]: go-librespot daemon starting... Aug 30 18:34:40 primo-plus sudo[2788]: pam_unix(sudo:session): session closed for user root Aug 30 18:34:40 primo-plus volumio[1092]: info: Connection to go-librespot Websocket closed Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=info msg="running go-librespot 0.7.1" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=debug msg="app state loaded" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=debug msg="stored credentials not found" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=info msg="zeroconf server listening on port 42311" Aug 30 18:34:40 primo-plus go-librespot[2797]: time="2026-08-30T18:34:40+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 18:34:40 primo-plus volumio[1092]: info: New Spotify access tokenBQB6pSfC7I... Aug 30 18:34:40 primo-plus volumio[1092]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 30 18:34:41 primo-plus volumio[1092]: verbose: New Socket.io Connection to 192.168.104.148 from 192.168.104.219 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=debug msg="obtained new client token: AAEpyz4WuL0hzIbLj2tY1CC4MUVpl2CM4wBLUDIkVjUzh9trX60QUsMsgTjZZGw23RdEO0XL4o8vlE3q2L2MpONjXbvPDSZLZlxzIVbmjmZfRn4YouZlePTGN2E76G7knTEzeaZQLalC04X32YE0aOO5Ny0UcFHBl+ITSODfqWVquJZDi8B8L6EchQxBjWCmlDQT9o+ycm5aaTUptPq9MCo19P/VmFViWkVPfBPYCrEsZAEw1z3F0w==" Aug 30 18:34:41 primo-plus volumio[1092]: SPOTIFY: User informations: {"account_id":"qtI6EIubwV","country":"JP","display_name":"Akinori Ito","email":"akinori0110@yahoo.co.jp","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31ilqejszxg23iz5olx4nv4ucjdm"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31ilqejszxg23iz5olx4nv4ucjdm","id":"31ilqejszxg23iz5olx4nv4ucjdm","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85e8846bb82d3424f2ad6a07ac","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82e8846bb82d3424f2ad6a07ac","width":64}],"product":"premium","type":"user","uri":"spotify:user:31ilqejszxg23iz5olx4nv4ucjdm"} Aug 30 18:34:41 primo-plus volumio[1092]: info: Spotify Successfully logged in Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 18:34:41 primo-plus volumio[1092]: info: [1788082481085] CoreMusicLibrary::Adding element Spotify Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 18:34:41 primo-plus volumio[1092]: Cannot find translation for source QOBUZ Aug 30 18:34:41 primo-plus volumio[1092]: Cannot find translation for source Spotify Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=debug msg="connected to ap-gae2.spotify.com:443" Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=debug msg="completed keyexchange" Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=debug msg="completed challenge" Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=info msg="authenticated AP" username="31************************dm" Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetVisibleSources Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:41 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 30 18:34:41 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:34:41 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:41 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:41 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:41 primo-plus volumio[1092]: info: Listing playlists Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 18:34:41 primo-plus go-librespot[2797]: time="2026-08-30T18:34:41+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 18:34:41 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:41 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 18:34:41 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 30 18:34:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:34:42 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:34:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:34:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:34:42 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:34:42 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:42 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:42 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 30 18:34:43 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 14. Aug 30 18:34:43 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:43 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 18:34:43 primo-plus upmpdcli[2806]: Could not open config: /tmp/upmpdcli.conf Aug 30 18:34:43 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:43 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 18:34:43 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:34:43 primo-plus volumio[1092]: info: go-librespot daemon successfully initialized Aug 30 18:34:43 primo-plus volumio[1092]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 18:34:43 primo-plus volumio[1092]: info: Received Get System Info Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 18:34:43 primo-plus volumio[1092]: info: Discovery: Getting this device information Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::volumioGetState Aug 30 18:34:43 primo-plus volumio[1092]: info: CorePlayQueue::getTrack 0 Aug 30 18:34:43 primo-plus volumio[1092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 18:34:44 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 30 18:34:44 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:44 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:44 primo-plus go-librespot[2807]: go-librespot daemon starting... Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=info msg="running go-librespot 0.7.1" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=debug msg="app state loaded" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=debug msg="stored credentials not found" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=info msg="zeroconf server listening on port 36329" Aug 30 18:34:44 primo-plus go-librespot[2808]: time="2026-08-30T18:34:44+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=debug msg="obtained new client token: AAHX7RIc0IFtfS4oUuuSuuPFo97BcbGArYVvuyRWXsuaHl7ey413ERrEd7TA5+PKm6lc2RH+QKKDqROA+nwGtJQXqUb7BzY0V5HotTw2+IAvnvamUz09db/ZR/Ygd6Vmr/MKjpoFK8BjHBqnb69tvlwTgWXLmmSe5tIJXVfMtbCPVqVU/i0/pzSWgGbRCT5oEwyahzO6VzjCwedSCiOtUYI1U+FiqxmOvP793ewHlfTh8DIspvW46g==" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=debug msg="completed keyexchange" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=debug msg="completed challenge" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=info msg="authenticated AP" username="31************************dm" Aug 30 18:34:45 primo-plus go-librespot[2808]: time="2026-08-30T18:34:45+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 18:34:45 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:45 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 18:34:46 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:34:46 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:34:46 primo-plus volumio[1092]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 18:34:46 primo-plus volumio[1092]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 18:34:48 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 30 18:34:48 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:48 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:48 primo-plus go-librespot[2817]: go-librespot daemon starting... Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=info msg="running go-librespot 0.7.1" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=debug msg="app state loaded" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=debug msg="stored credentials not found" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=info msg="zeroconf server listening on port 45003" Aug 30 18:34:48 primo-plus go-librespot[2818]: time="2026-08-30T18:34:48+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=debug msg="obtained new client token: AAHUQ1WWH6YDSbhujCmYu3zznpjvvzn4ndG6UfTVPTKxn8bMRpr5MqLBOYFieSQYtI7vOIEfnx92HH0kOzAYToVUN2pXt2sZ0zWiEd/xMs6fM9vS2kb2+uqPP/4GkgMwey8Ln8ACd0dB+//xPUrPYDXvjA44SyHKdUSWH93RyJjZwOT4cwXUIpJIquiIT7G5zHIGfEuviNQG16dsXOEb+UWaSooG0+yyzOVmw17F41VVvY9Y/FpRSw==" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=debug msg="completed keyexchange" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=debug msg="completed challenge" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=info msg="authenticated AP" username="31************************dm" Aug 30 18:34:49 primo-plus go-librespot[2818]: time="2026-08-30T18:34:49+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 18:34:49 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:49 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 18:34:49 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:34:49 primo-plus volumio[1092]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042, ...) Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042/char0043, ...) Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042/char0043/desc0045, ...) Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042/char0046, ...) Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042/char0046/desc0048, ...) Aug 30 18:34:51 primo-plus bluealsa[946]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_B5_28_06_70_BA/service0042/char0049, ...) Aug 30 18:34:52 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 30 18:34:52 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:52 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 18:34:52 primo-plus go-librespot[2842]: go-librespot daemon starting... Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=info msg="running go-librespot 0.7.1" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="app state loaded" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="stored credentials not found" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 18:34:52 primo-plus volumio[1092]: info: Initializing connection to go-librespot Websocket Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="new websocket client" Aug 30 18:34:52 primo-plus volumio[1092]: info: Connection to go-librespot Websocket established Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=info msg="zeroconf server listening on port 41341" Aug 30 18:34:52 primo-plus go-librespot[2843]: time="2026-08-30T18:34:52+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=debug msg="obtained new client token: AAGA4JaVcwzt3lXxTGeUMZh9o0AsCi7I0elmDKwb1hj7sKb693pQQCynoUO9GEGy3I5y6VT1V9TOT9QxVXPdVW5A3qajWY70WVVvY7LfDRGZkSBD1kUbiDj60ICmqbzXhZc686BRZk+CtZ3yKuLal6eCG+6ILkmRzn8HICjzEt1NUfvZqp6Bnfv0ux3+GtZ3XqgBrCxD1vZImQGgbiENXwgZC0E3rbroweYuS35w+unFejZRJEbi8A==" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=debug msg="connected to ap-gae2.spotify.com:443" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=debug msg="completed keyexchange" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=debug msg="completed challenge" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=info msg="authenticated AP" username="31************************dm" Aug 30 18:34:53 primo-plus go-librespot[2843]: time="2026-08-30T18:34:53+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 18:34:53 primo-plus volumio[1092]: info: Connection to go-librespot Websocket closed Aug 30 18:34:53 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 18:34:53 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 18:34:55 primo-plus volumio[1092]: info: Getting Spotify volume Aug 30 18:34:55 primo-plus volumio[1092]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 18:34:55 primo-plus volumio[1092]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 18:34:55 primo-plus volumio[1092]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 30 18:34:55 primo-plus volumio[1092]: errno: -111, Aug 30 18:34:55 primo-plus volumio[1092]: code: 'ECONNREFUSED', Aug 30 18:34:55 primo-plus volumio[1092]: syscall: 'connect', Aug 30 18:34:55 primo-plus volumio[1092]: address: '127.0.0.1', Aug 30 18:34:55 primo-plus volumio[1092]: port: 9879, Aug 30 18:34:55 primo-plus volumio[1092]: response: undefined Aug 30 18:34:55 primo-plus volumio[1092]: } Aug 30 18:34:55 primo-plus volumio[1092]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 18:34:56 primo-plus sudo[2866]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-30 18:33' Aug 30 18:34:56 primo-plus sudo[2866]: 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="ceea798be624bcca033d94ae449c2a749a9724f0" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="primoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed May 27 09:37:15 UTC 2026" VOLUMIO_VERSION="4.164" VOLUMIO_HARDWARE="cm4" VOLUMIO_DEVICENAME="CM4" VOLUMIO_VENDOR_MODEL="Volumio Primo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo Plus" VOLUMIO_HASH="c8e7083e83ff605518b1cfc23784b0e7"