Aug 25 11:09:03 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5843. Aug 25 11:09:03 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:03 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:03 primo-plus upmpdcli[14336]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:09:03 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:09:03 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:09:18 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5844. Aug 25 11:09:18 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:18 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:18 primo-plus upmpdcli[14366]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:09:18 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:09:18 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:09:28 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:28.917+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.148+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://www.googleapis.com duration=226.403064ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.190+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://securetoken.googleapis.com duration=270.611358ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.192+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://google.com duration=273.233388ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.263+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=345.748713ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.360+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=439.049995ms Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:29 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:09:29 primo-plus volumio[1179]: verbose: New Socket.io Connection to 192.168.0.158:3000 from 192.168.0.200 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.441+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=http://pushupdates.volumio.org duration=521.776033ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.472+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://functions.volumio.cloud duration=555.122514ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.473+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://functions.volumio.cloud duration=555.522007ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.480+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=557.744395ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.495+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=574.307017ms Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.543+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=https://database.volumio.cloud duration=624.466488ms Aug 25 11:09:29 primo-plus volumio[1179]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.709+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=http://plugins.volumio.org duration=790.69557ms Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 11:09:29 primo-plus volumio[1179]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 25 11:09:29 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:29 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:29 primo-plus volumio[1179]: info: Listing playlists Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetQueue Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreStateMachine::getQueue Aug 25 11:09:29 primo-plus volumio[1179]: info: CorePlayQueue::getQueue Aug 25 11:09:29 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:29.843+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=456.879753ms timeout=10s endpoint=http://cddb.volumio.org duration=923.523448ms Aug 25 11:09:29 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.758+08:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=445.222706ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.771+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.796+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://google.com duration=25.479395ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.861+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=90.187484ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.876+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://www.googleapis.com duration=104.939841ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.878+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=106.899622ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.878+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=107.463205ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.946+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://securetoken.googleapis.com duration=174.56592ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.953+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://functions.volumio.cloud duration=180.903218ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.957+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://functions.volumio.cloud duration=185.664266ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.961+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=189.786732ms Aug 25 11:09:31 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:31.980+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=https://database.volumio.cloud duration=207.89792ms Aug 25 11:09:32 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:32.033+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=http://pushupdates.volumio.org duration=261.119541ms Aug 25 11:09:32 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:32.149+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=http://plugins.volumio.org duration=377.339743ms Aug 25 11:09:32 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:32.214+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" latency=441.858755ms timeout=10s endpoint=http://cddb.volumio.org duration=443.440771ms Aug 25 11:09:32 primo-plus sudo[14383]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 11:09:32 primo-plus sudo[14383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:09:32 primo-plus sudo[14383]: pam_unix(sudo:session): session closed for user root Aug 25 11:09:32 primo-plus sudo[14385]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 11:09:32 primo-plus sudo[14385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:09:32 primo-plus sudo[14385]: pam_unix(sudo:session): session closed for user root Aug 25 11:09:32 primo-plus volumio[1179]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 10 Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 11:09:32 primo-plus sudo[14389]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 11:09:32 primo-plus sudo[14389]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:09:32 primo-plus sudo[14389]: pam_unix(sudo:session): session closed for user root Aug 25 11:09:32 primo-plus sudo[14391]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 11:09:32 primo-plus sudo[14391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:09:32 primo-plus sudo[14391]: pam_unix(sudo:session): session closed for user root Aug 25 11:09:32 primo-plus volumio[1179]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 10 Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 11:09:32 primo-plus volumio[1179]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 25 11:09:32 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:32 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:32 primo-plus volumio[1179]: info: Listing playlists Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 11:09:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 11:09:33 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5845. Aug 25 11:09:33 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:33 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:33 primo-plus upmpdcli[14394]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:09:33 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:09:33 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:09:34 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 1 Aug 25 11:09:34 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:09:34 primo-plus volumio[1179]: info: Prefetching next song Aug 25 11:09:34 primo-plus volumio[1179]: info: [1787627374063] ControllerTidal::prefetch Aug 25 11:09:34 primo-plus volumio[1179]: info: Getting stream with soundQuality LOSSLESS Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 11:09:34 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:34 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:34 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:09:35 primo-plus volumio[1179]: info: getStreamUrl took 1090 milliseconds Aug 25 11:09:35 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==" Aug 25 11:09:35 primo-plus volumio[1179]: info: Aug 25 11:09:35 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:35 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:35 primo-plus volumio[1179]: info: sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==" took 8 milliseconds Aug 25 11:09:35 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 25 11:09:35 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand consume 1 Aug 25 11:09:35 primo-plus volumio[1179]: info: Aug 25 11:09:35 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:35 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:35 primo-plus volumio[1179]: info: Aug 25 11:09:35 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:35 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:35 primo-plus volumio[1179]: info: ------------------------------ 5ms Aug 25 11:09:35 primo-plus volumio[1179]: info: sendMpdCommand consume 1 took 3 milliseconds Aug 25 11:09:35 primo-plus volumio[1179]: info: ------------------------------ 3ms Aug 25 11:09:35 primo-plus volumio[1179]: info: ------------------------------ 2ms Aug 25 11:09:35 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetQueue Aug 25 11:09:35 primo-plus volumio[1179]: info: CoreStateMachine::getQueue Aug 25 11:09:35 primo-plus volumio[1179]: info: CorePlayQueue::getQueue Aug 25 11:09:36 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 11:09:36 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:09:36 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:36 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:36 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:36 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:36 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:38 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:38 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces system playlist update Aug 25 11:09:38 primo-plus volumio[1179]: info: Ignoring MPD Status Update Aug 25 11:09:38 primo-plus volumio[1179]: info: Aug 25 11:09:38 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 3ms Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand status took 3 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 3ms Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand status took 2 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 2ms Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand status took 2 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:09:38 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 1 Aug 25 11:09:38 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":476,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"296 Kbps","isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:09:38 primo-plus volumio[1179]: verbose: CURRENT POSITION 1 Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService play Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus play Aug 25 11:09:38 primo-plus volumio[1179]: info: Received an update from plugin. extracting info from payload Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 1 Aug 25 11:09:38 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":476,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"296 Kbps","isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:09:38 primo-plus volumio[1179]: verbose: CURRENT POSITION 1 Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService play Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus play Aug 25 11:09:38 primo-plus volumio[1179]: info: Received an update from plugin. extracting info from payload Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 1 Aug 25 11:09:38 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":476,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"296 Kbps","isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:09:38 primo-plus volumio[1179]: verbose: CURRENT POSITION 1 Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService play Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus play Aug 25 11:09:38 primo-plus volumio[1179]: info: Received an update from plugin. extracting info from payload Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:38 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.535+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.535+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.535+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.535+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.537+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.538+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.538+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.538+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.538+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.539+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=670365 volume=100 Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:38.540+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 55ms Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 55ms Aug 25 11:09:38 primo-plus volumio[1179]: info: ------------------------------ 54ms Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:38 primo-plus volumio[1179]: info: CoreStateMachine::startPlaybackTimer Aug 25 11:09:38 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:09:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:09:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:09:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 11:09:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:09:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:09:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:09:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:09:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:39.030+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=251 volume=100 Aug 25 11:09:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:39.030+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=251 volume=100 Aug 25 11:09:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:39.031+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201199 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: II. Adagio" Aug 25 11:09:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:09:39.031+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201199 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: II. Adagio" Aug 25 11:09:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:09:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:09:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:09:40 primo-plus volumio[1179]: Searching plugin music_service/mpd Aug 25 11:09:40 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , search Aug 25 11:09:40 primo-plus volumio[1179]: info: All search sources collected, pushing search results Aug 25 11:09:42 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 25 11:09:46 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: tidal , handleBrowseUri Aug 25 11:09:47 primo-plus volumio[1179]: info: browseTIDALUri took 291 milliseconds Aug 25 11:09:47 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:09:47 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:09:48 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5846. Aug 25 11:09:48 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:48 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:09:49 primo-plus upmpdcli[14435]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:09:49 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:09:49 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:09:51 primo-plus volumio[1179]: Searching plugin music_service/tidal Aug 25 11:09:51 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: tidal , search Aug 25 11:09:51 primo-plus volumio[1179]: info: searchTIDALUri took 587 milliseconds Aug 25 11:09:51 primo-plus volumio[1179]: info: search took 589 milliseconds Aug 25 11:09:51 primo-plus volumio[1179]: info: All search sources collected, pushing search results Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 11:09:52 primo-plus volumio[1179]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 25 11:09:52 primo-plus volumio[1179]: info: Received Get System Version Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 11:09:52 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:09:52 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:09:52 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:09:52 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:10:04 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5847. Aug 25 11:10:04 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:04 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:04 primo-plus upmpdcli[14453]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:10:04 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:04 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:10:11 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 11:10:11 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 25 11:10:15 primo-plus volumio[1179]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 11:10:19 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5848. Aug 25 11:10:19 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:19 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:19 primo-plus upmpdcli[14485]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:10:19 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:19 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:10:22 primo-plus volumio[1179]: info: Received OAUTH Data Aug 25 11:10:22 primo-plus volumio[1179]: info: Executing Spotify Oauth Login Aug 25 11:10:22 primo-plus volumio[1179]: info: Saving Spotify Refresh Token Aug 25 11:10:22 primo-plus sudo[14488]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 11:10:22 primo-plus sudo[14488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:10:22 primo-plus sudo[14488]: pam_unix(sudo:session): session closed for user root Aug 25 11:10:22 primo-plus sudo[14490]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 11:10:22 primo-plus sudo[14490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:10:22 primo-plus sudo[14490]: pam_unix(sudo:session): session closed for user root Aug 25 11:10:22 primo-plus volumio[1179]: verbose: New Socket.io Connection to 192.168.0.158 from 192.168.0.200 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 11:10:22 primo-plus volumio[1179]: info: New Spotify access tokenBQDlTa93c5... Aug 25 11:10:22 primo-plus volumio[1179]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:22 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 11:10:22 primo-plus volumio[1179]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 25 11:10:22 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:10:22 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:22 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:22 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:22 primo-plus volumio[1179]: info: Listing playlists Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 11:10:22 primo-plus volumio[1179]: SPOTIFY: User informations: {"account_id":"5nsZgnVIAl","country":"TW","display_name":"黃柏勛","email":"sweetchild0505@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11155833586"},"followers":{"href":null,"total":29},"href":"https://api.spotify.com/v1/users/11155833586","id":"11155833586","images":[{"height":300,"url":"https://scontent-tpe1-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=100&ccb=1-7&_nc_sid=08baa4&_nc_ohc=Lvn1LP5x0q8Q7kNvwGfGziY&_nc_oc=Adr8BHyCL7lwujb4xSizq64U7u3ypYiSFZnFyWvsldXSWgYV6bSOAkrrosd3OPt7-kUb8PStDMe7y-RXVe7DvGXt&_nc_zt=24&_nc_ht=scontent-tpe1-1.xx&edm=AP4hL3IEAAAA&_nc_gid=OsQCRPIw_v15lSMMmnTaiQ&_nc_tpa=Q5bMBQLGE0VxaBOiprHPb2tW5oagDt1WA_la7b5Z9Toqj_YqSyH7xgZ36N6X347QNv8wNBTS7zgQ&oh=00_AQEPP6sZmJpMimC2dw_vuX3a1I6aTY5s2-il7S5g3eiEhw&oe=6A92A40F","width":300},{"height":64,"url":"https://scontent-tpe1-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=100&ccb=1-7&_nc_sid=28885b&_nc_ohc=Lvn1LP5x0q8Q7kNvwGfGziY&_nc_oc=Adr8BHyCL7lwujb4xSizq64U7u3ypYiSFZnFyWvsldXSWgYV6bSOAkrrosd3OPt7-kUb8PStDMe7y-RXVe7DvGXt&_nc_zt=24&_nc_ht=scontent-tpe1-1.xx&edm=AP4hL3IEAAAA&_nc_gid=OsQCRPIw_v15lSMMmnTaiQ&_nc_tpa=Q5bMBQJDAgtwYf_9GcKIJc3jqs4LFRLCec5BQsMZZYX51fpVAuv9z7hCtc4eAhnS30-Df45Id-so&oh=00_AQEIMcFVCWPn7OAtvAwL3YghAObwEpBRgy8RFWv6_ifNEQ&oe=6A92A40F","width":64}],"product":"premium","type":"user","uri":"spotify:user:11155833586"} Aug 25 11:10:22 primo-plus volumio[1179]: info: Creating Spotify config file Aug 25 11:10:22 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 11:10:23 primo-plus volumio[1179]: info: Spotify config file written Aug 25 11:10:23 primo-plus sudo[14495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 11:10:23 primo-plus sudo[14495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:10:23 primo-plus systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 25 11:10:23 primo-plus systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 25 11:10:23 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:23 primo-plus systemd[1]: go-librespot-daemon.service: Consumed 6.322s CPU time. Aug 25 11:10:23 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 11:10:23 primo-plus volumio[1179]: info: Connection to go-librespot Websocket closed Aug 25 11:10:23 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:23 primo-plus go-librespot[14497]: go-librespot daemon starting... Aug 25 11:10:23 primo-plus sudo[14495]: pam_unix(sudo:session): session closed for user root Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="app state loaded" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08: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 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08: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 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08: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 25 11:10:23 primo-plus volumio[1179]: info: New Spotify access tokenBQAZ0L_cn-... Aug 25 11:10:23 primo-plus volumio[1179]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=info msg="zeroconf server listening on port 35637" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="obtained new client token: AAG9y0JqbSjECWtQ1mPWXPAVjEqhcnaIEqpsMFJ5Adpsh0GzsUcz9BrNPr3417OSXBvweebiLanwAY3TYQRxoci9Rf+fO39xO6NAW8WUubQYQbJT2VsGT3V+kgj/BcIMbCzZOluWDuq+K4ikU/OoqhM8JgDx5ll2u5ZDLZf28IcOCfUQZpUJFXiZFN3IxJc2epojxjCrGJ7f64TVokSlwJabjVxm9xsaF2rxrszJyTTSPTQst8oyZXpX" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=debug msg="completed challenge" Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:23 primo-plus volumio[1179]: SPOTIFY: User informations: {"account_id":"5nsZgnVIAl","country":"TW","display_name":"黃柏勛","email":"sweetchild0505@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11155833586"},"followers":{"href":null,"total":29},"href":"https://api.spotify.com/v1/users/11155833586","id":"11155833586","images":[{"height":300,"url":"https://scontent-tpe1-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=100&ccb=1-7&_nc_sid=08baa4&_nc_ohc=Lvn1LP5x0q8Q7kNvwGfGziY&_nc_oc=Adr8BHyCL7lwujb4xSizq64U7u3ypYiSFZnFyWvsldXSWgYV6bSOAkrrosd3OPt7-kUb8PStDMe7y-RXVe7DvGXt&_nc_zt=24&_nc_ht=scontent-tpe1-1.xx&edm=AP4hL3IEAAAA&_nc_gid=OsQCRPIw_v15lSMMmnTaiQ&_nc_tpa=Q5bMBQLGE0VxaBOiprHPb2tW5oagDt1WA_la7b5Z9Toqj_YqSyH7xgZ36N6X347QNv8wNBTS7zgQ&oh=00_AQEPP6sZmJpMimC2dw_vuX3a1I6aTY5s2-il7S5g3eiEhw&oe=6A92A40F","width":300},{"height":64,"url":"https://scontent-tpe1-1.xx.fbcdn.net/v/t39.30808-1/325243218_1388804191925385_4571018935575687877_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=100&ccb=1-7&_nc_sid=28885b&_nc_ohc=Lvn1LP5x0q8Q7kNvwGfGziY&_nc_oc=Adr8BHyCL7lwujb4xSizq64U7u3ypYiSFZnFyWvsldXSWgYV6bSOAkrrosd3OPt7-kUb8PStDMe7y-RXVe7DvGXt&_nc_zt=24&_nc_ht=scontent-tpe1-1.xx&edm=AP4hL3IEAAAA&_nc_gid=OsQCRPIw_v15lSMMmnTaiQ&_nc_tpa=Q5bMBQJDAgtwYf_9GcKIJc3jqs4LFRLCec5BQsMZZYX51fpVAuv9z7hCtc4eAhnS30-Df45Id-so&oh=00_AQEIMcFVCWPn7OAtvAwL3YghAObwEpBRgy8RFWv6_ifNEQ&oe=6A92A40F","width":64}],"product":"premium","type":"user","uri":"spotify:user:11155833586"} Aug 25 11:10:23 primo-plus volumio[1179]: info: Spotify Successfully logged in Aug 25 11:10:23 primo-plus volumio[1179]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 11:10:23 primo-plus volumio[1179]: info: [1787627423365] CoreMusicLibrary::Adding element Spotify Aug 25 11:10:23 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 11:10:23 primo-plus volumio[1179]: Cannot find translation for source TIDAL Aug 25 11:10:23 primo-plus volumio[1179]: Cannot find translation for source Spotify Aug 25 11:10:23 primo-plus go-librespot[14498]: time="2026-08-25T11:10:23+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:23 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:23 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 11:10:24 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:10:24 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:24 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:24 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:10:25 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 11:10:25 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:10:25 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:10:25 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:10:25 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:10:25 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:25 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:25 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:10:26 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetQueue Aug 25 11:10:26 primo-plus volumio[1179]: info: CoreStateMachine::getQueue Aug 25 11:10:26 primo-plus volumio[1179]: info: CorePlayQueue::getQueue Aug 25 11:10:26 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:26 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:26 primo-plus volumio[1179]: info: go-librespot daemon successfully initialized Aug 25 11:10:26 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 25 11:10:26 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:26 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:26 primo-plus go-librespot[14507]: go-librespot daemon starting... Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="app state loaded" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08: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 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08: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 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08: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 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=info msg="zeroconf server listening on port 44455" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="obtained new client token: AAGb/cCNWdAt+B6GUrqDT5a8JTOuZg/GbjUzpBafmsB5hihsU+T0rySZcIR5Wvnqz9zmmI1xHjqAE9L2ANAiSabqMQl5Lc8utSB2XqPgRV4KD6bwJIuPMHgpUDnZ/5H7fGY2pfkXO/JFHUMPL+LFAH5FF4OSHhJoF2Yfge0bruPrJCWyolBtkaMPH5vDNtCX8kn0r5OvFOJr+TR9X70rpfkLAmF76u1flp2LOG8MembkdTvxHYx5R5jA" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=debug msg="completed challenge" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:26 primo-plus go-librespot[14508]: time="2026-08-25T11:10:26+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:26 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:26 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:28 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Aug 25 11:10:28 primo-plus volumio[1179]: info: In handleBrowseUri, curUri=spotify Aug 25 11:10:28 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:28 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:28 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:28 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:29 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:29 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:29 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:29 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:29 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 25 11:10:29 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:29 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:29 primo-plus go-librespot[14532]: go-librespot daemon starting... Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="app state loaded" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08: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 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08: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 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08: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 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=info msg="zeroconf server listening on port 43589" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="obtained new client token: AAEdRm9/zGTJfq8IeTFcjxQIyKCXMGRT4ylJZF77ALPlCvVzsYAO7OoPnLdq8UmyWIxQlrGwurqhUrzKvXAyWcqsFjhIkKDAJZ+5P0WeTYPBM0xXq7gSLQMxqz742xGWecQ1y3chrsumnWlJRFtNjtaWvmmMqgRtlZM+46/Sa07J7jzBi8pM17QVrkUyzE7gZfJWRlhwzuurbA/+SanCLrxts4gv5RIbLQkIsb9h0lcYA9o3IwSmLw==" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=debug msg="completed challenge" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:30 primo-plus go-librespot[14533]: time="2026-08-25T11:10:30+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:30 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:30 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:31 primo-plus volumio[1179]: Searching plugin music_service/spop Aug 25 11:10:31 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , search Aug 25 11:10:32 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:32 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:32 primo-plus volumio[1179]: info: All search sources collected, pushing search results Aug 25 11:10:32 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 25 11:10:33 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 25 11:10:33 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:33 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:33 primo-plus go-librespot[14542]: go-librespot daemon starting... Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="app state loaded" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08: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 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08: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 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08: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 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=info msg="zeroconf server listening on port 36341" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="obtained new client token: AAEPbZyV4SUsorcMtf0J3M4UspZikeH94yLZf/Q1F1DjEiEWmp7KAGwiT+/xTu8gUUbO2hGuZaIoKLUYWP/IgubdSJvwe9G3SSGLHIKkW0YsGWCUX7977ny9MEhWTiFpyF3+QxsiSPrPi8OJMyHMzMmmP3b0YqM4J6j0qSb+W3dZW+MaBix506xadMhDHpHN7rNoEsaVDOOa3NW1+9qg5zcCiptiPu3chCR6X5ValPxKL896dyeOut3I" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08: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 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=debug msg="completed challenge" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:33 primo-plus go-librespot[14543]: time="2026-08-25T11:10:33+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:33 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:33 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:34 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5849. Aug 25 11:10:34 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:34 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 25 11:10:34 primo-plus upmpdcli[14553]: Could not open config: /tmp/upmpdcli.conf Aug 25 11:10:34 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:34 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 25 11:10:35 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:35 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:36 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 25 11:10:36 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:36 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:36 primo-plus go-librespot[14555]: go-librespot daemon starting... Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="app state loaded" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08: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 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08: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 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08: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 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=info msg="zeroconf server listening on port 36295" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="obtained new client token: AAGGgwxWa4K0041S0qykMMBZ+5LjUAWBuRccwceNvhNZKPF89erQOggT6G6EnbmR6lysJ/MmDI4uh7AE1HruS79NBZwtrKJ3IJNv9xhcaA/P8EscIsEBPyqAWf1as059k94okXkFWqfRMIfsnNE0He4Ca6mJP1+v5p1uPKzvKUQE1J95akZjGCU4T+xGUbX49yc1oTfR8QZ5Zi/t+XVg/KB6Xv9AQDfjDIkNM1va7KymBj8eMqgiOA==" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=debug msg="completed challenge" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:37 primo-plus go-librespot[14556]: time="2026-08-25T11:10:37+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:37 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:37 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:38 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:38 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:39 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::ClearQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::stPlaybackTimer Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::updateTrackBlock Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrackBlock Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::serviceStop Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::serviceStop Aug 25 11:10:39 primo-plus volumio[1179]: info: [1787627439131] ControllerTidal::stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::stop Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::clearPlayQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::addQueueItems Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::addQueueItems Aug 25 11:10:39 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0kg6Y7Cg2fOPcFU4ID101V Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:0kg6Y7Cg2fOPcFU4ID101V in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:0kg6Y7Cg2fOPcFU4ID101V Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.144+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_STOPPED positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.144+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_STOPPED positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.145+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201199 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: II. Adagio" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.145+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201199 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: II. Adagio" Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Aug 25 11:10:39 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand stop took 40 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:10:39 primo-plus volumio[1179]: info: Aug 25 11:10:39 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:10:39 primo-plus volumio[1179]: info: Aug 25 11:10:39 primo-plus volumio[1179]: ---------------------------- MPD announces state update: player Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::getState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand status took 4 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand status took 9 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand status took 9 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseState Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:10:39 primo-plus volumio[1179]: verbose: CURRENT POSITION 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: No code Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.208+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.210+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.212+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.212+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.212+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.213+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.213+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.212+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.218+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.218+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.219+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.219+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio[1179]: info: ------------------------------ 60ms Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 50 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: info: sendMpdCommand playlistinfo took 50 milliseconds Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:10:39 primo-plus volumio[1179]: verbose: ControllerMpd::parseTrackInfo Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:10:39 primo-plus volumio[1179]: verbose: CURRENT POSITION 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: No code Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: ControllerMpd::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::servicePushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:39 primo-plus volumio[1179]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEiczOGMyM2U5ZDMyMjVhYzIyODVjMjc1MWNjMzdhMjllZl82MS5tcDQ/0.flac?token=1787630974~OWIzNDFlMWRhZWFjNjAzNWI3N2YxZTIzNmFmMzk2MzA1ZDQxNjk0ZQ==","trackType":"tidal"} Aug 25 11:10:39 primo-plus volumio[1179]: verbose: CURRENT POSITION 2 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState stateService stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::syncState currentStatus stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio[1179]: info: No code Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::pushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output update for this device Aug 25 11:10:39 primo-plus volumio[1179]: info: MRS: Pushing multiroomSync output Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.256+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.257+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.257+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.258+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.259+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.259+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.259+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.260+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.260+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.261+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.261+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.261+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.261+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.261+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.262+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.266+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.266+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.267+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.266+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.269+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.269+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" state=STATUS_PLAYING positionMs=0 volume=100 Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.269+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.0.200:53798 @ 0x2800360" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.270+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio5-onboarding[1926]: time=2026-08-25T11:10:39.271+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.200:53798 @ 0x2800600" id=tidal://song/27201198 title="Brahms: Violin Sonata No. 1 in G Major, Op. 78: I. Vivace ma non troppo" Aug 25 11:10:39 primo-plus volumio[1179]: info: ------------------------------ 116ms Aug 25 11:10:39 primo-plus volumio[1179]: info: ------------------------------ 116ms Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: info: Signalling Playback active due to playback status change Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: Updating RAAT Signal Path Aug 25 11:10:39 primo-plus volumio[1179]: info: MCU Signalled Playback Inactive Aug 25 11:10:39 primo-plus volumio[1179]: info: MCU Signalled Playback Active Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0kg6Y7Cg2fOPcFU4ID101V","service":"spop","name":"新不了情","artist":"Wanfang","album":"斷線","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b2738f45d85560bb54eb56099f40","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::updateTrackBlock Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrackBlock Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPlay Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::play index 0 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::addQueueItems Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::addQueueItems Aug 25 11:10:39 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4heoK6zUM7ElZyytFgnrrk Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:4heoK6zUM7ElZyytFgnrrk in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:4heoK6zUM7ElZyytFgnrrk Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1KFyrwqxqBky7ezRII71JN Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:1KFyrwqxqBky7ezRII71JN in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:1KFyrwqxqBky7ezRII71JN Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3Ue54BzmJG4AAV7rkHSTt5 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:3Ue54BzmJG4AAV7rkHSTt5 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:3Ue54BzmJG4AAV7rkHSTt5 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:7MpySBn5TEIkOm6qoZtE15 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:7MpySBn5TEIkOm6qoZtE15 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:7MpySBn5TEIkOm6qoZtE15 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1lDcSpEHm1lsnpL4avG2hg Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:1lDcSpEHm1lsnpL4avG2hg in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:1lDcSpEHm1lsnpL4avG2hg Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1qSnfG6dFPlAo6kq8OAVED Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:1qSnfG6dFPlAo6kq8OAVED in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:1qSnfG6dFPlAo6kq8OAVED Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:5l94Up12BJSjhH7Mhr2ji4 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:5l94Up12BJSjhH7Mhr2ji4 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:5l94Up12BJSjhH7Mhr2ji4 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3iSUQPIvnhSOI97sfWMhix Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:3iSUQPIvnhSOI97sfWMhix in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:3iSUQPIvnhSOI97sfWMhix Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0WoIUZZwAkxXQdoeqfRVA4 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:0WoIUZZwAkxXQdoeqfRVA4 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:0WoIUZZwAkxXQdoeqfRVA4 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:6H7SbivrPcg4roR8x6LL0T Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:6H7SbivrPcg4roR8x6LL0T in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:6H7SbivrPcg4roR8x6LL0T Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1fZhClIljIAn0qC2E0JMAo Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:1fZhClIljIAn0qC2E0JMAo in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:1fZhClIljIAn0qC2E0JMAo Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:72IyhK4qYuUEF6poH5lMwZ Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:72IyhK4qYuUEF6poH5lMwZ in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:72IyhK4qYuUEF6poH5lMwZ Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0eBahbjGENaT8DdB8WhHTe Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:0eBahbjGENaT8DdB8WhHTe in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:0eBahbjGENaT8DdB8WhHTe Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4fnL7MXjueXC9wvjWLDuQa Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:4fnL7MXjueXC9wvjWLDuQa in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:4fnL7MXjueXC9wvjWLDuQa Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4Ate1rLOyiVyi9CQjWmJx2 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:4Ate1rLOyiVyi9CQjWmJx2 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:4Ate1rLOyiVyi9CQjWmJx2 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:66jZ9gBmYWLWAEiiYqUsj9 Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:66jZ9gBmYWLWAEiiYqUsj9 in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:66jZ9gBmYWLWAEiiYqUsj9 Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3IP4qSMfGeqI2XqHFf25sj Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:3IP4qSMfGeqI2XqHFf25sj in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:3IP4qSMfGeqI2XqHFf25sj Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1Mf48xXtjI0psEeSEXMxio Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:1Mf48xXtjI0psEeSEXMxio in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:1Mf48xXtjI0psEeSEXMxio Aug 25 11:10:39 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:2T8ppyUVF1TJT1Mjd7nmWK Aug 25 11:10:39 primo-plus volumio[1179]: info: Exploding uri spotify:track:2T8ppyUVF1TJT1Mjd7nmWK in service spop Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: EXPLODING URI:spotify:track:2T8ppyUVF1TJT1Mjd7nmWK Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::stop Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::play index undefined Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 0 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::startPlaybackTimer Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 0 Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 25 11:10:39 primo-plus volumio[1179]: info: [1787627439400] ControllerSpotify::clearAddPlayTrack Aug 25 11:10:39 primo-plus volumio[1179]: info: Sending Spotify command with payload to local API: /player/play Aug 25 11:10:39 primo-plus volumio[1179]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5l94Up12BJSjhH7Mhr2ji4","service":"spop","name":"紅豆","artist":"Faye Wong","album":"唱遊","type":"song","duration":256,"albumart":"https://i.scdn.co/image/594bdf55f84c78b398f25c310cd055ede6d73c27","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3iSUQPIvnhSOI97sfWMhix","service":"spop","name":"新不了情","artist":"Wanfang","album":"ONE 芳新歌+精選","type":"song","duration":267,"albumart":"https://i.scdn.co/image/ab67616d0000b2731663fe30eb10a17e75c80945","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0WoIUZZwAkxXQdoeqfRVA4","service":"spop","name":"新不了情","artist":"Wanfang","album":"新不了情電影原聲帶","type":"song","duration":267,"albumart":"https://i.scdn.co/image/ab67616d0000b273e5db8a6c904ac30fab3a61d8","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6H7SbivrPcg4roR8x6LL0T","service":"spop","name":"新不了情 - 粵語版","artist":"Wanfang","album":"芳心精選輯","type":"song","duration":267,"albumart":"https://i.scdn.co/image/ab67616d0000b273d528b5144e8fb12cdd33c643","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4heoK6zUM7ElZyytFgnrrk","service":"spop","name":"新不了情","artist":"黃小琥","album":"The Voice 現場演唱全紀錄","type":"song","duration":278,"albumart":"https://i.scdn.co/image/ab67616d0000b27357451899b7c742515a215786","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3IP4qSMfGeqI2XqHFf25sj","service":"spop","name":"芒种","artist":"音阙诗听","album":"芒种","type":"song","duration":216,"albumart":"https://i.scdn.co/image/ab67616d0000b273886dfb1845ff392d548ed540","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Ue54BzmJG4AAV7rkHSTt5","service":"spop","name":"新不了情 - 滾石撞樂隊2 (原唱:萬芳)","artist":"我是機車少女","album":"滾石撞樂隊2 - 新不了情","type":"song","duration":351,"albumart":"https://i.scdn.co/image/ab67616d0000b27344a3edfd2c1c599dbf524957","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7MpySBn5TEIkOm6qoZtE15","service":"spop","name":"新不了情（つきせぬ想い）","artist":"Kaori Kobayashi","album":"SEVENth","type":"song","duration":298,"albumart":"https://i.scdn.co/image/ab67616d0000b2734be1ec3890bfc790b476e3b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0eBahbjGENaT8DdB8WhHTe","service":"spop","name":"DJ小庭不要停","artist":"C.Holly","album":"三不娶","type":"song","duration":105,"albumart":"https://i.scdn.co/image/ab67616d0000b273bcc5f1854f1f10d5e6e8d027","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:66jZ9gBmYWLWAEiiYqUsj9","service":"spop","name":"再見 Puppy Love","artist":"林姍姍","album":"陳百強不朽金曲金藏集","type":"song","duration":219,"albumart":"https://i.scdn.co/image/ab67616d0000b27307550256685eba4daaabf682","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1qSnfG6dFPlAo6kq8OAVED","service":"spop","name":"我只在乎你","artist":"Teresa Teng","album":"我只在乎你","type":"song","duration":252,"albumart":"https://i.scdn.co/image/ab67616d0000b27383ce9f50a676383703ee4b2c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1lDcSpEHm1lsnpL4avG2hg","service":"spop","name":"不了情 & 新不了情","artist":"Tsai Chin","album":"遇見","type":"song","duration":443,"albumart":"https://i.scdn.co/image/ab67616d0000b273cfd4bde7b11db614e5ab50fe","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1fZhClIljIAn0qC2E0JMAo","service":"spop","name":"你怎麼捨得我難過 - 滾石撞樂隊2 (原唱:黃品源)","artist":"Wendy Wander","album":"滾石撞樂隊2 - 你怎麼捨得我難過","type":"song","duration":251,"albumart":"https://i.scdn.co/image/ab67616d0000b273a10c92382049cf7db2eedcd2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:72IyhK4qYuUEF6poH5lMwZ","service":"spop","name":"新不了情","artist":"Harlem Yu","album":"新不了情","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab6742d3000053b7385bfc96192b9ca7c961e13e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1Mf48xXtjI0psEeSEXMxio","service":"spop","name":"青春大概 (電視劇《我在未來等你》青春主題曲)","artist":"王上","album":"電視劇《我在未來等你》原聲專輯","type":"song","duration":226,"albumart":"https://i.scdn.co/image/ab67616d0000b273c621a30ae7f971d7852bd4e7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1KFyrwqxqBky7ezRII71JN","service":"spop","name":"新不了情","artist":"Wanfang","album":"芳心精選輯","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b273d528b5144e8fb12cdd33c643","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2T8ppyUVF1TJT1Mjd7nmWK","service":"spop","name":"永久損毀","artist":"MC 張天賦","album":"TREBLE","type":"song","duration":232,"albumart":"https://i.scdn.co/image/ab67616d0000b2730bf55fcd403ae0cb3feb31ca","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4Ate1rLOyiVyi9CQjWmJx2","service":"spop","name":"再見 PUPPY LOVE","artist":"Ellen Loo","album":"一期一會","type":"song","duration":272,"albumart":"https://i.scdn.co/image/ab67616d0000b273c0fedd1c82c26f8aab526053","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4fnL7MXjueXC9wvjWLDuQa","service":"spop","name":"再見 Puppy Love","artist":"林姍姍","album":"我愛經典系列","type":"song","duration":219,"albumart":"https://i.scdn.co/image/ab67616d0000b2739b99e49bea3c6a11d4831cb9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:39 primo-plus volumio[1179]: info: CoreStateMachine::updateTrackBlock Aug 25 11:10:39 primo-plus volumio[1179]: info: CorePlayQueue::getTrackBlock Aug 25 11:10:40 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 25 11:10:40 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:40 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:40 primo-plus go-librespot[14588]: go-librespot daemon starting... Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="app state loaded" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08: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 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08: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 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08: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 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=info msg="zeroconf server listening on port 42219" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="obtained new client token: AAFHRzaeSdznUEz/6bX51vNAMVK9QpYUQg+40HpGoqnxJy0IsgiLqfPbsc5MCRd63hw8m9yRdDnvmJwlGhdvV4oC3lcFmJLlMlpfcIhymSJ6uHUGsmn6ZZsh6V/lvlrXfGd+TVN99b+LVRLGhUTPTGgPXUMVUMQIIS4o9JDpp5Hggwt06jnjxTZbCQSWHBYmLRNHA6RNitcQCtRxnfio3pLejHbvCzmptgF/wVUiAPJtcYDMZymer7J/" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=debug msg="completed challenge" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:40 primo-plus go-librespot[14589]: time="2026-08-25T11:10:40+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:40 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:40 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:41 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:41 primo-plus volumio[1179]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 11:10:41 primo-plus volumio[1179]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 25 11:10:41 primo-plus volumio[1179]: info: Received Get System Version Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 11:10:41 primo-plus volumio[1179]: info: Received Get System Info Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 11:10:41 primo-plus volumio[1179]: info: Discovery: Getting this device information Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 0 Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 11:10:41 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::ClearQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::stop Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::clearPlayQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::addQueueItems Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::addQueueItems Aug 25 11:10:41 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0kg6Y7Cg2fOPcFU4ID101V Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:0kg6Y7Cg2fOPcFU4ID101V Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4heoK6zUM7ElZyytFgnrrk Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:4heoK6zUM7ElZyytFgnrrk Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1KFyrwqxqBky7ezRII71JN Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:1KFyrwqxqBky7ezRII71JN Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::updateTrackBlock Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrackBlock Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioGetState Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 0 Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPlay Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::play index 2 Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::addQueueItems Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::addQueueItems Aug 25 11:10:41 primo-plus volumio[1179]: info: Preload queue cleared Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3Ue54BzmJG4AAV7rkHSTt5 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:3Ue54BzmJG4AAV7rkHSTt5 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:7MpySBn5TEIkOm6qoZtE15 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:7MpySBn5TEIkOm6qoZtE15 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1lDcSpEHm1lsnpL4avG2hg Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:1lDcSpEHm1lsnpL4avG2hg Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1qSnfG6dFPlAo6kq8OAVED Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:1qSnfG6dFPlAo6kq8OAVED Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:5l94Up12BJSjhH7Mhr2ji4 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:5l94Up12BJSjhH7Mhr2ji4 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3iSUQPIvnhSOI97sfWMhix Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:3iSUQPIvnhSOI97sfWMhix Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0WoIUZZwAkxXQdoeqfRVA4 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:0WoIUZZwAkxXQdoeqfRVA4 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:6H7SbivrPcg4roR8x6LL0T Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:6H7SbivrPcg4roR8x6LL0T Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1fZhClIljIAn0qC2E0JMAo Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:1fZhClIljIAn0qC2E0JMAo Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:72IyhK4qYuUEF6poH5lMwZ Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:72IyhK4qYuUEF6poH5lMwZ Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:0eBahbjGENaT8DdB8WhHTe Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:0eBahbjGENaT8DdB8WhHTe Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4fnL7MXjueXC9wvjWLDuQa Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:4fnL7MXjueXC9wvjWLDuQa Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:4Ate1rLOyiVyi9CQjWmJx2 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:4Ate1rLOyiVyi9CQjWmJx2 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:66jZ9gBmYWLWAEiiYqUsj9 Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:66jZ9gBmYWLWAEiiYqUsj9 Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:3IP4qSMfGeqI2XqHFf25sj Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:3IP4qSMfGeqI2XqHFf25sj Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:1Mf48xXtjI0psEeSEXMxio Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:1Mf48xXtjI0psEeSEXMxio Aug 25 11:10:41 primo-plus volumio[1179]: info: Adding Item to queue: spotify:track:2T8ppyUVF1TJT1Mjd7nmWK Aug 25 11:10:41 primo-plus volumio[1179]: info: Using cached record of: spotify:track:2T8ppyUVF1TJT1Mjd7nmWK Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::stop Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreCommandRouter::volumioPushQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::saveQueue Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::play index undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::updateTrackBlock Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrackBlock Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:41 primo-plus volumio[1179]: info: CoreStateMachine::startPlaybackTimer Aug 25 11:10:41 primo-plus volumio[1179]: info: CorePlayQueue::getTrack 2 Aug 25 11:10:41 primo-plus volumio[1179]: info: [1787627441563] ControllerSpotify::clearAddPlayTrack Aug 25 11:10:41 primo-plus volumio[1179]: info: Sending Spotify command with payload to local API: /player/play Aug 25 11:10:41 primo-plus volumio[1179]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:43 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 25 11:10:43 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:43 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:43 primo-plus go-librespot[14599]: go-librespot daemon starting... Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="app state loaded" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:44 primo-plus volumio[1179]: info: Initializing connection to go-librespot Websocket Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="new websocket client" Aug 25 11:10:44 primo-plus volumio[1179]: info: Connection to go-librespot Websocket established Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08: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 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08: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 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08: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 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=info msg="zeroconf server listening on port 43005" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="obtained new client token: AAFC9Z76lOiDItNhiWADTxPfhWvOUUoeKVHTIFo8LDoH1SeMpgds8G+Arsd+TL7XlAsXDDCo9GnQVPKHu2t60QRnPh29LFFj4zgvXIRJk0Ck6WuQapLhHYOZoVOwsVDSxiZqE0YGsrXDZZc1ZNBcX+Iy7GG/eB5RU7V2sOT/DKAVNuzgoW/BRseWBaV6fem7Nz2EpWvWeRl8kEkSZVSdWTepZx+h/y5A/wFNIGOHuTopWdOuLwblTQ==" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="completed keyexchange" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=debug msg="completed challenge" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=info msg="authenticated AP" username="11*******86" Aug 25 11:10:44 primo-plus go-librespot[14600]: time="2026-08-25T11:10:44+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 11:10:44 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 11:10:44 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 11:10:44 primo-plus volumio[1179]: info: Connection to go-librespot Websocket closed Aug 25 11:10:47 primo-plus volumio[1179]: info: Getting Spotify volume Aug 25 11:10:47 primo-plus volumio[1179]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 11:10:47 primo-plus volumio[1179]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 11:10:47 primo-plus volumio[1179]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 11:10:47 primo-plus volumio[1179]: errno: -111, Aug 25 11:10:47 primo-plus volumio[1179]: code: 'ECONNREFUSED', Aug 25 11:10:47 primo-plus volumio[1179]: syscall: 'connect', Aug 25 11:10:47 primo-plus volumio[1179]: address: '127.0.0.1', Aug 25 11:10:47 primo-plus volumio[1179]: port: 9879, Aug 25 11:10:47 primo-plus volumio[1179]: response: undefined Aug 25 11:10:47 primo-plus volumio[1179]: } Aug 25 11:10:47 primo-plus volumio[1179]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 11:10:47 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 11:10:47 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:47 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 11:10:47 primo-plus go-librespot[14635]: go-librespot daemon starting... Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=info msg="running go-librespot 0.7.1" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=debug msg="app state loaded" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=debug msg="stored credentials not found" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08: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 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08: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 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08: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 25 11:10:47 primo-plus sudo[14645]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 11:09' Aug 25 11:10:47 primo-plus sudo[14645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=info msg="zeroconf server listening on port 39523" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 11:10:47 primo-plus go-librespot[14636]: time="2026-08-25T11:10:47+08:00" level=debug msg="obtained new client token: AAGVPD2FVddgZ44sJlzzRDD+69nIzXvDwTxX5aoD/bXGCSQP701I4yJFaOwS/rK/j6imLtc/YAWY93Monny3ZabgLQS/9Ts7ENf3ZLZsXqo0eJ+/VEB7mG/oOGUuh18y+tnvSdXZpvWJTf+8LdgkIPzY0Vf48SAz9/nkXLDRvbD3xO5PzzCM92FRvB0xIXKKQmn1dPbBs5lfYkj2YUky5j3vZrBuSX/Kb6upFgj45fQGOX+vTdSNIcHk" 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"