Aug 28 14:28:49 primo-plus ntpd[915]: CLOCK: time stepped by 8045468.665854 Aug 28 14:28:49 primo-plus ntpd[915]: CLOCK: time changed from 2026-05-27 to 2026-08-28 Aug 28 14:28:49 primo-plus ntpd[915]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 28 14:28:52 primo-plus volumio[1183]: info: Loading plugin "tidalconnect"... Aug 28 14:28:52 primo-plus volumio[1183]: info: Loading plugin "webradio"... Aug 28 14:28:53 primo-plus volumio[1183]: info: Loading plugin "i2s_dacs"... Aug 28 14:28:53 primo-plus volumio[1183]: info: I2S DAC not set, start Auto-detection Aug 28 14:28:53 primo-plus volumio[1183]: info: Loading plugin "volumiodiscovery"... Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** For more information see Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 14:28:53 primo-plus volumio[1183]: *** WARNING *** For more information see Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** For more information see Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 14:28:53 primo-plus node[1183]: *** WARNING *** For more information see Aug 28 14:28:53 primo-plus volumio[1183]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 14:28:53 primo-plus volumio[1183]: info: Discovery: Started advertising with name: Primo Plus Aug 28 14:28:53 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 14:28:53 primo-plus volumio[1183]: info: Loading plugin "calmradio"... Aug 28 14:28:54 primo-plus volumio[1183]: info: Loading plugin "spop"... Aug 28 14:28:54 primo-plus systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 28 14:28:54 primo-plus systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 28 14:28:54 primo-plus systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 28 14:28:54 primo-plus systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 28 14:28:54 primo-plus systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 28 14:28:54 primo-plus systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 28 14:28:55 primo-plus sh[697]: timed out Aug 28 14:28:55 primo-plus dhcpcd[705]: timed out Aug 28 14:28:55 primo-plus sh[632]: ifup: failed to bring up eth0 Aug 28 14:28:55 primo-plus systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:28:55 primo-plus systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 28 14:28:55 primo-plus volumio[1183]: info: Loading plugin "multiroom"... Aug 28 14:28:56 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 28 14:28:56 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 14:28:56 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 14:28:56 primo-plus upmpdcli[1847]: Could not open config: /tmp/upmpdcli.conf Aug 28 14:28:56 primo-plus systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:28:56 primo-plus systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 28 14:28:57 primo-plus volumio[1183]: info: Applying required configuration parameters for plugin multiroom Aug 28 14:28:57 primo-plus sudo[1850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Aug 28 14:28:57 primo-plus sudo[1850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:28:57 primo-plus sudo[1850]: pam_unix(sudo:session): session closed for user root Aug 28 14:28:57 primo-plus volumio[1183]: info: MRS: MultiRoom plugin initialized Aug 28 14:28:57 primo-plus volumio[1183]: info: MRS: STOPPING SNAPCLIENT Aug 28 14:28:57 primo-plus volumio[1183]: info: MRS: Snap server stop Aug 28 14:28:57 primo-plus volumio[1183]: info: MRS: STOPPING volumioStreaming Aug 28 14:28:57 primo-plus sudo[1867]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Aug 28 14:28:57 primo-plus sudo[1867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:28:57 primo-plus volumio[1183]: info: Loading plugin "outputs"... Aug 28 14:28:57 primo-plus sudo[1871]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Aug 28 14:28:57 primo-plus sudo[1871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:28:57 primo-plus sudo[1869]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Aug 28 14:28:57 primo-plus sudo[1869]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:28:57 primo-plus volumio[1183]: info: Loading plugin "albumart"... Aug 28 14:28:57 primo-plus sudo[1874]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Aug 28 14:28:57 primo-plus sudo[1874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:28:57 primo-plus sudo[1874]: pam_unix(sudo:session): session closed for user root Aug 28 14:28:57 primo-plus volumio[1183]: info: Plugin example_plugin is not enabled Aug 28 14:28:57 primo-plus volumio[1183]: info: Loading plugin "hi_res_audio"... Aug 28 14:28:57 primo-plus sudo[1867]: pam_unix(sudo:session): session closed for user root Aug 28 14:28:57 primo-plus sudo[1871]: pam_unix(sudo:session): session closed for user root Aug 28 14:28:57 primo-plus sudo[1869]: pam_unix(sudo:session): session closed for user root Aug 28 14:28:57 primo-plus systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 28 14:28:57 primo-plus volumio[1878]: Forking 3 albumart workers Aug 28 14:28:58 primo-plus volumio[1892]: Starting albumart workers Aug 28 14:28:58 primo-plus volumio[1891]: Starting albumart workers Aug 28 14:28:58 primo-plus volumio[1893]: Starting albumart workers Aug 28 14:28:58 primo-plus volumio[1183]: info: Applying required configuration parameters for plugin hi_res_audio Aug 28 14:28:58 primo-plus volumio[1183]: info: Loading plugin "inputs"... Aug 28 14:28:59 primo-plus volumio[1183]: info: Loading plugin "qobuz"... Aug 28 14:29:00 primo-plus volumio[1183]: info: Loading plugin "smart_inputs"... Aug 28 14:29:00 primo-plus volumio[1183]: info: Loading plugin "tidal"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading plugin "primopluscontrol"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Initializing System Ready GPIO for kernel version: 6.12.75-v8+ Aug 28 14:29:01 primo-plus volumio[1183]: info: Adding this device properties Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setThisDeviceVolumioProperties Aug 28 14:29:01 primo-plus volumio[1183]: info: Setting Additional Device Volumio Properties: [object Object] Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading plugin "updater_comm"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Plugin mpdemulation is not enabled Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading plugin "rest_api"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading plugin "websocket"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Starting Socket.io Server version 1.7.4 Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading plugin "radio_paradise"... Aug 28 14:29:01 primo-plus volumio[1183]: info: Applying required configuration parameters for plugin radio_paradise Aug 28 14:29:01 primo-plus volumio[1183]: info: [1787920141732] [RadioParadise] API delay: 5 Aug 28 14:29:01 primo-plus volumio[1183]: info: Loading i18n strings for locale it Aug 28 14:29:01 primo-plus volumio[1183]: Updating browse sources language Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::initPlayerControls Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 14:29:01 primo-plus volumio[1183]: Express server listening on port 3000 Aug 28 14:29:01 primo-plus volumio[1183]: [Metrics] WebUI: 20s 836.59ms Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreStateMachine::resetVolumioState Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreStateMachine::getcurrentVolume Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:01 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:01 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:01 primo-plus sudo[1954]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 14:29:01 primo-plus sudo[1954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus sudo[1954]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus sudo[1956]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 14:29:02 primo-plus sudo[1956]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus sudo[1956]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus volumio[1183]: info: Volumio Network Manager: Network status updated: 2 Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: Removed streaming files Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: volumioStreaming STOPPED Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: SNAPSERVER STOPPED Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: SNAPCLIENT STOPPED Aug 28 14:29:02 primo-plus volumio[1183]: info: Reloading queue from file Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreStateMachine::setRepeat null single undefined Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:02 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreStateMachine::setRandom null Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:02 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:02 primo-plus volumio[1183]: info: Setting Device type: Raspberry PI Aug 28 14:29:02 primo-plus volumio[1183]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Aug 28 14:29:02 primo-plus volumio[1183]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03141 Aug 28 14:29:02 primo-plus volumio[1183]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Aug 28 14:29:02 primo-plus volumio[1183]: info: Completed loading Core Plugins Aug 28 14:29:02 primo-plus volumio[1183]: info: Preparing to generate the ALSA configuration file Aug 28 14:29:02 primo-plus sudo[1968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 14:29:02 primo-plus sudo[1968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus volumio[1183]: info: Discovery: adding 0f857cde-ab5f-4ca6-93ac-a1e5b9fc3c93 Aug 28 14:29:02 primo-plus volumio[1183]: info: Discovery: Found device Primo Plus Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:02 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output for this device Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding audio output: Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding audio output: Aug 28 14:29:02 primo-plus volumio[1183]: info: Discovery: this is already registered, 0f857cde-ab5f-4ca6-93ac-a1e5b9fc3c93 Aug 28 14:29:02 primo-plus volumio[1183]: info: Discovery: Found device Primo Plus Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:02 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:02 primo-plus volumio[1183]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 28 14:29:02 primo-plus volumio[1183]: info: Reading ALSA contributions from plugins. Aug 28 14:29:02 primo-plus volumio[1183]: info: Asound.conf file unchanged, so no further update is needed Aug 28 14:29:02 primo-plus volumio[1183]: info: Output device has changed, restarting MPD Aug 28 14:29:02 primo-plus volumio[1183]: info: Output device has changed, restarting Shairport Sync Aug 28 14:29:02 primo-plus sudo[1971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 14:29:02 primo-plus sudo[1971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:02 primo-plus sudo[1971]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus sudo[1973]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 14:29:02 primo-plus sudo[1973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus volumio[1183]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 14:29:02 primo-plus volumio[1183]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: ___________ START PLUGINS ___________ Aug 28 14:29:02 primo-plus systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 14:29:02 primo-plus systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 14:29:02 primo-plus volumio[1183]: info: ControllerMpd::onStart: Initializing MPD Aug 28 14:29:02 primo-plus volumio[1183]: info: Creating MPD Configuration file Aug 28 14:29:02 primo-plus sudo[1987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 14:29:02 primo-plus sudo[1987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus sudo[1987]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:02 primo-plus volumio[1183]: info: [1787920142544] CoreMusicLibrary::Adding element Server multimediali Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:02 primo-plus sudo[1985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 14:29:02 primo-plus sudo[1985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus volumio[1183]: info: UPNP Browser: Client initialized successfully Aug 28 14:29:02 primo-plus sudo[1990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 14:29:02 primo-plus sudo[1990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:02 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: [FUNC] onStart Aug 28 14:29:02 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Aug 28 14:29:02 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Aug 28 14:29:02 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Aug 28 14:29:02 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding METAVOLUMIO REST API Endpoints Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:02 primo-plus systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 14:29:02 primo-plus bluetoothd[922]: Path / reserved for Adv Monitor app :1.19 Aug 28 14:29:02 primo-plus sudo[1985]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus systemd[1]: mpd.service: Deactivated successfully. Aug 28 14:29:02 primo-plus systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 14:29:02 primo-plus systemd[1]: mpd.socket: Deactivated successfully. Aug 28 14:29:02 primo-plus systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 14:29:02 primo-plus systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 14:29:02 primo-plus systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 14:29:02 primo-plus bluetoothd[922]: Adv Monitor app :1.19 disconnected from D-Bus Aug 28 14:29:02 primo-plus volumio[1183]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 14:29:02 primo-plus systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 14:29:02 primo-plus volumio[1183]: info: Preparing CD Folders Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding CD REST API Endpoints Aug 28 14:29:02 primo-plus volumio[1183]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Aug 28 14:29:02 primo-plus volumio[1183]: info: Starting UDEV Watcher for CD Aug 28 14:29:02 primo-plus volumio[1183]: info: Detecting CD presence with UDEV Aug 28 14:29:02 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Aug 28 14:29:02 primo-plus sudo[2005]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 14:29:02 primo-plus sudo[2005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 14:29:02 primo-plus sudo[2014]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 28 14:29:02 primo-plus sudo[2005]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:02 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:02.998+02:00 level=INFO msg="running volumio5-device-gateway" version=83ee4468+CHANGES buildDate=2026-04-15T10:25:32Z Aug 28 14:29:03 primo-plus volumio-remote-updater[757]: [2026-08-28 14:29:03] [connect] Successful connection Aug 28 14:29:05 primo-plus mpd[2015]: 2026-08-28T14:29:05 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 14:29:05 primo-plus systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 14:29:05 primo-plus sudo[1990]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:05 primo-plus sudo[1973]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:07 primo-plus volumio[1183]: warn: [cd-plugin] cdspeedctl: device or media not ready Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:07 primo-plus volumio[1183]: info: [1787920147753] CoreMusicLibrary::Adding element Last_100 Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:07 primo-plus volumio[1183]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Aug 28 14:29:07 primo-plus volumio[1183]: info: QobuzConnect: Starting Qobuz Connect socket and service Aug 28 14:29:07 primo-plus volumio[1183]: info: Starting RAAT Plugin Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Aug 28 14:29:07 primo-plus volumio[1183]: info: Additional UI Settings Added for plugin music_service/raat Aug 28 14:29:07 primo-plus volumio[1183]: info: Registering DSP Elements listener and retrieving current ones Aug 28 14:29:07 primo-plus volumio[1183]: info: Additional DSP elements updated Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:07 primo-plus volumio[1183]: info: Updating RAAT Signal Path Aug 28 14:29:07 primo-plus volumio[1183]: error: Cannot write to RAAT Client: TypeError: Cannot read properties of undefined (reading 'write') Aug 28 14:29:07 primo-plus volumio[1183]: info: Streaming services startup Aug 28 14:29:07 primo-plus volumio[1183]: info: Starting Streaming Daemon Aug 28 14:29:07 primo-plus sudo[2057]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 28 14:29:07 primo-plus sudo[2057]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:07 primo-plus sudo[2061]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 14:29:07 primo-plus sudo[2061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:07 primo-plus volumio[1183]: info: [1787920147843] CoreMusicLibrary::Adding element Webradio Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:07 primo-plus sudo[2057]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 14:29:07 primo-plus sudo[2061]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:07 primo-plus volumio[1183]: info: Initializing BBC Radios Aug 28 14:29:07 primo-plus sudo[2069]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 28 14:29:07 primo-plus sudo[2069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:07 primo-plus sudo[2070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 28 14:29:07 primo-plus sudo[2070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:07 primo-plus volumio[1183]: info: Adding Calm Radio to Browse Sources Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:07 primo-plus volumio[1183]: info: [1787920147912] CoreMusicLibrary::Adding element Calm Radio Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:07 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:07 primo-plus volumio[1183]: info: Creating Spotify config file Aug 28 14:29:07 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:07 primo-plus systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 28 14:29:07 primo-plus sudo[2070]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:07 primo-plus sudo[2069]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Aug 28 14:29:08 primo-plus volumio[1183]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: error: Hi Res Audio Failed Login: Missing Login Data Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding HIGHRESAUDIO REST API Endpoints Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Aug 28 14:29:08 primo-plus volumio[1183]: info: Initializing Serial Communication on port /dev/ttyAMA4 Aug 28 14:29:08 primo-plus volumio[1183]: info: Touch Event Listener Process Starting Aug 28 14:29:08 primo-plus volumio[1183]: info: Refreshing QOBUZ token Aug 28 14:29:08 primo-plus sudo[2092]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/xinput --test-xi2 --root Aug 28 14:29:08 primo-plus sudo[2092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding inputs REST Endpoints Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Aug 28 14:29:08 primo-plus volumio[1183]: info: Scanning Audio Inputs Aug 28 14:29:08 primo-plus volumio[1183]: info: Checking against Known Cards name Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding Server instance for streaming Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:08 primo-plus volumio[1183]: info: [1787920148188] CoreMusicLibrary::Adding element Radio Paradise Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:08 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:08 primo-plus volumio[1183]: Cannot find translation for source Radio Paradise Aug 28 14:29:08 primo-plus volumio[1183]: info: Volumio Calling Home Aug 28 14:29:08 primo-plus volumio[1183]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Aug 28 14:29:08 primo-plus volumio[1183]: (node:1183) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Aug 28 14:29:08 primo-plus volumio[1183]: (Use `node --trace-deprecation ...` to show where the warning was created) Aug 28 14:29:08 primo-plus volumio[1183]: info: Adding TIDAL REST API Endpoints Aug 28 14:29:08 primo-plus volumio[1183]: info: Serial port opened successfully Aug 28 14:29:08 primo-plus volumio[1183]: info: Sending serial start messages Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: Reporting MCU Network Status: 2 Aug 28 14:29:08 primo-plus volumio[1183]: error: Cannot start Volumio Streaming Daemon Aug 28 14:29:08 primo-plus volumio[1183]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 14:29:08 primo-plus volumio[1183]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 14:29:08 primo-plus volumio[1183]: info: RAAT Albumart path created successfully Aug 28 14:29:08 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Aug 28 14:29:08 primo-plus volumio[1183]: info: MPD Permissions set Aug 28 14:29:08 primo-plus volumio[1183]: info: MPD Permissions set Aug 28 14:29:08 primo-plus sudo[2104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setDeviceVolumeOverride Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting Device Volume Override Aug 28 14:29:08 primo-plus sudo[2104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus volumio[1183]: info: Applying Volume Override Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 28 14:29:08 primo-plus volumio[1183]: info: Updating Volume Controller Parameters: Device: 0 Name: Analog Outputs Mixer: Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 28 14:29:08 primo-plus volumio[1183]: info: Enabling external Volume Control Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: inputs , updateVolumeSettings Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: inputs , retrievevolume Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:08 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:08 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:08 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:08 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:08 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 28 14:29:08 primo-plus systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 28 14:29:08 primo-plus sudo[2104]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumio[1183]: info: Volumio called home Aug 28 14:29:08 primo-plus volumio[1183]: info: Spotify config file written Aug 28 14:29:08 primo-plus volumiobt[2113]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 28 14:29:08 primo-plus sudo[2115]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 28 14:29:08 primo-plus sudo[2117]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 14:29:08 primo-plus sudo[2115]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus sudo[2117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 28 14:29:08 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:08 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:08 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:08 primo-plus sudo[2115]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:08.514+02:00 level=INFO msg="system info for 2b2919f5f2f2364456b65bee9b1759f9" deviceName="Primo Plus" deviceVariant=primoplus deviceModel="Volumio Primo Plus" softwareVersion=4.164 Aug 28 14:29:08 primo-plus systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 14:29:08 primo-plus systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 14:29:08 primo-plus sudo[2120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 28 14:29:08 primo-plus sudo[2120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:08.536+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 28 14:29:08 primo-plus sudo[2120]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumiobt[2123]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 28 14:29:08 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:08 primo-plus go-librespot[2122]: go-librespot daemon starting... Aug 28 14:29:08 primo-plus sudo[2117]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumio[1183]: error: MPD error: The expression evaluated to a falsy value: Aug 28 14:29:08 primo-plus volumio[1183]: assert.ok(self.idling) Aug 28 14:29:08 primo-plus volumio[1183]: error: The expression evaluated to a falsy value: Aug 28 14:29:08 primo-plus volumio[1183]: assert.ok(self.idling) Aug 28 14:29:08 primo-plus volumio-remote-updater[757]: [2026-08-28 14:29:08] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787920143 101 Aug 28 14:29:08 primo-plus bluetoothd[922]: Adv Monitor app :1.23 disconnected from D-Bus Aug 28 14:29:08 primo-plus volumiobt[2127]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 28 14:29:08 primo-plus volumio[1183]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Aug 28 14:29:08 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Aug 28 14:29:08 primo-plus volumio[1183]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Aug 28 14:29:08 primo-plus volumio[1183]: info: MPD running with PID2015 Aug 28 14:29:08 primo-plus volumio[1183]: ,establishing connection Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumiobt[2128]: [176B blob data] Aug 28 14:29:08 primo-plus volumiobt[2128]: [157B blob data] Aug 28 14:29:08 primo-plus volumiobt[2128]: [157B blob data] Aug 28 14:29:08 primo-plus volumiobt[2128]: [157B blob data] Aug 28 14:29:08 primo-plus volumiobt[2128]: [113B blob data] Aug 28 14:29:08 primo-plus volumiobt[2128]: [bluetoothctl]> discoverable on Aug 28 14:29:08 primo-plus volumiobt[2128]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Aug 28 14:29:08 primo-plus volumiobt[2128]: [bluetoothctl]> pairable on Aug 28 14:29:08 primo-plus bluetoothd[922]: Path / reserved for Adv Monitor app :1.24 Aug 28 14:29:08 primo-plus bluetoothd[922]: Adv Monitor app :1.24 disconnected from D-Bus Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumiobt[2128]: [bluetoothctl]> Aug 28 14:29:08 primo-plus volumiobt[2143]: INFO [BTSTART] Registering Bluetooth agent... Aug 28 14:29:08 primo-plus volumio[1183]: info: No need to fix Spotify hosts Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting Additional System Software info: Hardware Revision: 1.1 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting HW Firmware info: undefined Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting HW Version info: 1.1 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting Additional System Software info: Hardware Revision: 1.1, Firmware Version: 0.5.4 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting HW Firmware info: 0.5.4 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Aug 28 14:29:08 primo-plus volumio[1183]: info: Setting HW Version info: 1.1 Aug 28 14:29:08 primo-plus volumio[1183]: info: MCU Signalled PowerOff Capabilities, enabling MCU Poweroff Aug 28 14:29:08 primo-plus volumio[1183]: info: MCU Signalled Headphone Mode Disabled Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Aug 28 14:29:08 primo-plus volumio[1183]: info: Reporting Headphone State: false Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:08 primo-plus volumio[1183]: info: Updating RAAT Signal Path Aug 28 14:29:08 primo-plus volumio[1183]: error: Cannot write to RAAT Client: TypeError: Cannot read properties of undefined (reading 'write') Aug 28 14:29:08 primo-plus volumio[1183]: info: MCU Signalled Sleep Mode Disabled Aug 28 14:29:08 primo-plus volumio[1183]: info: Enabling Advanced system settings configuration Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , addAdditionalUISections Aug 28 14:29:08 primo-plus volumio[1183]: info: Additional UI Settings Added for plugin music_service/inputs Aug 28 14:29:08 primo-plus volumio[1183]: info: MCU Signalled Auto Boot Mode On Power Disabled Aug 28 14:29:08 primo-plus volumio[1183]: info: MCU Signalled NOS Mode Disabled Aug 28 14:29:08 primo-plus volumiobt[2144]: [NEW] Media /org/bluez/hci0 Aug 28 14:29:08 primo-plus volumiobt[2144]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus volumiobt[2144]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus volumiobt[2144]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:08 primo-plus bluetoothd[922]: Adv Monitor app :1.25 disconnected from D-Bus Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:08 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:08 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:08 primo-plus sudo[2146]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Aug 28 14:29:08 primo-plus sudo[2146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:08 primo-plus volumio[1183]: error: updateQueue error: null Aug 28 14:29:08 primo-plus sudo[2146]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:08 primo-plus volumiobt[2148]: No agent is registered Aug 28 14:29:08 primo-plus volumiobt[2148]: [NEW] Media /org/bluez/hci0 Aug 28 14:29:08 primo-plus volumiobt[2148]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus volumiobt[2148]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus volumiobt[2148]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 28 14:29:08 primo-plus bluetoothd[922]: Adv Monitor app :1.27 disconnected from D-Bus Aug 28 14:29:08 primo-plus volumiobt[2150]: INFO [BTSTART] Agent registered successfully. Aug 28 14:29:08 primo-plus volumiobt[2151]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 28 14:29:08 primo-plus go-librespot[2126]: time="2026-08-28T14:29:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:08 primo-plus go-librespot[2126]: time="2026-08-28T14:29:08+02:00" level=debug msg="app state loaded" Aug 28 14:29:08 primo-plus go-librespot[2126]: time="2026-08-28T14:29:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:08 primo-plus volumio[1183]: info: Executing endpoint qc_getconfig Aug 28 14:29:08 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 28 14:29:08 primo-plus qobuz-connect[2086]: 20260828 14:29:08.921 [2086.2086] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 28 14:29:08 primo-plus volumio[1183]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Aug 28 14:29:08 primo-plus volumio[1183]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Aug 28 14:29:08 primo-plus volumio-remote-updater[757]: Test mode disabled Aug 28 14:29:08 primo-plus volumio-remote-updater[757]: Alpha mode disabled Aug 28 14:29:08 primo-plus volumio-remote-updater[757]: Alpha legacy test mode disabled Aug 28 14:29:09 primo-plus volumio[1183]: info: Access Token successfully retrieved Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:09 primo-plus volumio[1183]: info: [1787920149013] CoreMusicLibrary::Adding element QOBUZ Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Radio Paradise Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source QOBUZ Aug 28 14:29:09 primo-plus volumio[1183]: info: Stopping AccessToken refresher cron for QOBUZ Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.023 [2086.2086] INFO VolumeManager: [0x1197138]: Setting new playback volume: 75 Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.023 [2086.2086] INFO VolumeManager: [0x1197138]: Setting new mute state: 0 Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.023 [2086.2086] INFO AudioStreamManager: [0x1196e90]: Setting new audio download buffer size: 1048576 Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.023 [2086.2086] INFO QobuzConnect: [0x1197a00]: Client initialized! Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.023 [2086.2086] INFO SampleApp: Starting Avahi advertising, name: Primo Plus, service name: _qobuz-connect._tcp Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.044 [2086.2086] INFO LocalConfigManager: [0x1196bb8]: Starting Local Configuration server Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.044 [2086.2086] INFO SampleApp: Starting Local configuration server Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.045 [2086.2086] INFO SampleApp: Connected to UNIX socket client 0x11818f8 Aug 28 14:29:09 primo-plus volumio[1183]: info: AccessToken refresher cron started for QOBUZ Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding QOBUZ REST API Endpoints Aug 28 14:29:09 primo-plus qobuz-connect[2086]: 20260828 14:29:09.072 [2086.2086] INFO SampleApp: Playback volume changed: 75 Aug 28 14:29:09 primo-plus volumio[1183]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 28 14:29:09 primo-plus volumio[1183]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:09 primo-plus sudo[2162]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Aug 28 14:29:09 primo-plus sudo[2162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:09 primo-plus sudo[2162]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:09 primo-plus volumio[1183]: error: updateQueue error: null Aug 28 14:29:09 primo-plus volumio[1183]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: Starting Shairport Sync Aug 28 14:29:09 primo-plus volumio[1183]: info: Starting Shairport Sync Aug 28 14:29:09 primo-plus volumio[1183]: info: Starting Shairport Sync Aug 28 14:29:09 primo-plus sudo[2168]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 14:29:09 primo-plus sudo[2168]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:09 primo-plus sudo[2170]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 14:29:09 primo-plus sudo[2170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=info msg="zeroconf server listening on port 44431" Aug 28 14:29:09 primo-plus sudo[2173]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 14:29:09 primo-plus sudo[2173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:09 primo-plus systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 14:29:09 primo-plus systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 14:29:09 primo-plus systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 14:29:09 primo-plus systemd[1]: shairport-sync.service: Consumed 1.911s CPU time. Aug 28 14:29:09 primo-plus volumio[1183]: info: New Spotify access tokenBQD_JctoJy... Aug 28 14:29:09 primo-plus volumio[1183]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:09 primo-plus systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 14:29:09 primo-plus sudo[2173]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:09 primo-plus sudo[2170]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:09 primo-plus sudo[2168]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding Inputs via Serial API Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:09 primo-plus volumio[1183]: info: [1787920149419] CoreMusicLibrary::Adding element Inputs Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Radio Paradise Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source QOBUZ Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding Advanced Audio Settings via Serial API Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Aug 28 14:29:09 primo-plus volumio[1183]: info: Additional UI Settings Added for plugin music_service/inputs Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding Advanced Audio Settings via Serial API Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="obtained new client token: AAFrPTN/HKcHXjBt2M8DiXo2hcy2/so3rTPGh7Bf5bxIdsBbIZhj20QtpMKBecdme6BUMHl6eGhL8acw6SYCWP1HVi85C62VqG0/KDWNH4ROP14POWruB1NW5sJkLF/yLuDkMvki1wIA3pbSAQcyjJr86B9nsrpVpGtI2GGeZBHGQUfQwrgA30xv0gnYE6uaMdpODlXCjI1S1A1HHae/Yss1MH2ar6vOXyKMYP/D/IkHj0TBU0h8QOqaKw==" Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding Advanced Audio Settings via Serial API Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Found cast device: Google-Nest-Mini-afafcbd74a112ee80ee212a945bf2f29 Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding audio output: Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=debug msg="completed challenge" Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding audio output: Aug 28 14:29:09 primo-plus volumio[1183]: info: Adding audio output: Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:09 primo-plus volumio[1183]: info: Shairport-Sync Started Aug 28 14:29:09 primo-plus volumio[1183]: Error adding Membership: Error: addMembership EINVAL Aug 28 14:29:09 primo-plus volumio[1183]: info: Shairport-Sync Started Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:09 primo-plus go-librespot[2126]: time="2026-08-28T14:29:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:09 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:09 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:09 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 28 14:29:09 primo-plus volumio[1183]: info: Shairport-Sync Started Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::servicePushState Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:09 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current calmradio Received inputs Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumiosetSourceActiveno-source Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source Radio Paradise Aug 28 14:29:09 primo-plus volumio[1183]: Cannot find translation for source QOBUZ Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Connecting to system D-Bus Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Connected to system D-Bus Aug 28 14:29:09 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:09 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:09 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 bluezutils [INFO] Found adapter at: /org/bluez/hci0 Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Found Bluetooth adapter: /org/bluez/hci0 Aug 28 14:29:09 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Set DiscoverableTimeout to infinite Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Enabled Discoverable mode Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Agent registered at /local/a2dpagent Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] Agent set as default Aug 28 14:29:09 primo-plus volumiobt[2152]: 2026-08-28 14:29:09 a2dp-agent [INFO] A2DP agent running, waiting for connections... Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 14:29:09 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 14:29:09 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:09.897+02:00 level=INFO msg="enabling local network discovery" Aug 28 14:29:09 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:09.916+02:00 level=INFO msg="enabling BLE discovery" Aug 28 14:29:10 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:10 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:10 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:10 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:10 primo-plus volumio[1183]: SPOTIFY: User informations: {"account_id":"REjTHsmRBY","country":"IT","display_name":"enasturzio","email":"emilio.nasturzio@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/enasturzio"},"followers":{"href":null,"total":2},"href":"https://api.spotify.com/v1/users/enasturzio","id":"enasturzio","images":[],"product":"premium","type":"user","uri":"spotify:user:enasturzio"} Aug 28 14:29:10 primo-plus volumio[1183]: info: Spotify Successfully logged in Aug 28 14:29:10 primo-plus volumio[1183]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 14:29:10 primo-plus volumio[1183]: info: [1787920150137] CoreMusicLibrary::Adding element Spotify Aug 28 14:29:10 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:10 primo-plus volumio[1183]: Cannot find translation for source Calm Radio Aug 28 14:29:10 primo-plus volumio[1183]: Cannot find translation for source Radio Paradise Aug 28 14:29:10 primo-plus volumio[1183]: Cannot find translation for source QOBUZ Aug 28 14:29:10 primo-plus volumio[1183]: Cannot find translation for source Spotify Aug 28 14:29:10 primo-plus volumio[1183]: info: MCU Signalled Playback Inactive Aug 28 14:29:10 primo-plus volumio[1183]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: volumiokiosk-touch Engine version: 3 Transport: polling Total Clients: 5 Aug 28 14:29:10 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:10.948+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 14:29:10 primo-plus volumio[1183]: info: TidalConnect service stoped! Aug 28 14:29:11 primo-plus volumio[1183]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 28 14:29:11 primo-plus volumio[1183]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 28 14:29:11 primo-plus sudo[2209]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 28 14:29:11 primo-plus sudo[2209]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:11 primo-plus systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 28 14:29:11 primo-plus systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Aug 28 14:29:11 primo-plus sudo[2209]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:11 primo-plus volumio[1183]: info: Initializing I2S Bus Aug 28 14:29:11 primo-plus volumio[1183]: info: Executing endpoint tc_getconfig Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 28 14:29:11 primo-plus vtcs[2215]: STARTING TidalConnect services, version: 1.6.1 Aug 28 14:29:11 primo-plus vtcs[2215]: STARTED TidalConnect services. Aug 28 14:29:11 primo-plus volumio[1183]: info: Executing endpoint tc_connect Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 28 14:29:11 primo-plus volumio[1183]: info: Connecting to TidalConnect Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::servicePushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:11 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current calmradio Received tidalconnect Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::servicePushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreStateMachine::pushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::volumioPushState Aug 28 14:29:11 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output update for this device Aug 28 14:29:11 primo-plus volumio[1183]: info: MRS: Pushing multiroomSync output Aug 28 14:29:11 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:11 primo-plus volumio[1183]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current calmradio Received tidalconnect Aug 28 14:29:11 primo-plus volumio[1183]: info: go-librespot daemon successfully initialized Aug 28 14:29:12 primo-plus systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 28 14:29:12 primo-plus systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 14:29:12 primo-plus systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 14:29:12 primo-plus sudo[1968]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:12 primo-plus volumio[1183]: info: Upmpdcli Daemon Started Aug 28 14:29:12 primo-plus volumio[1183]: info: Successfully initialized I2S Bus Aug 28 14:29:12 primo-plus volumio[1183]: error: Serial API: Failed to decode command: LEDCOLOR, message: 2 Aug 28 14:29:12 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 14:29:12 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:12 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:12 primo-plus go-librespot[2273]: go-librespot daemon starting... Aug 28 14:29:12 primo-plus go-librespot[2274]: time="2026-08-28T14:29:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:12 primo-plus go-librespot[2274]: time="2026-08-28T14:29:12+02:00" level=debug msg="app state loaded" Aug 28 14:29:12 primo-plus go-librespot[2274]: time="2026-08-28T14:29:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=info msg="zeroconf server listening on port 43293" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:13 primo-plus volumio[1183]: info: MRS: Getting audio outputs on start Aug 28 14:29:13 primo-plus volumio[1183]: info: MRS: Requesting all other devices output Aug 28 14:29:13 primo-plus systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 28 14:29:13 primo-plus systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="obtained new client token: AAGfa2A61QOMq4sW1DbI7ftwKBi5RMP0BBfI0JtV0Ic+wzpVDdA53KQpO8i164EGgN7m8c6J3M63dGFSlrbDjBuu+Fpb7Y+MZ0LbH/Vd4Fga+kgHOM9lxrxT2dK2vTxc3+Ky49bMqarRnPZaX02DJWtA67zoL3gD2tKmC9WDNmg9tWrMFrnqhpht9SUi+iVlJRsDmXj/ss3nj9iVwLe892TLHosqC2DefLBLoxPwhjulkuvnEMCslIo=" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=debug msg="completed challenge" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:13 primo-plus go-librespot[2274]: time="2026-08-28T14:29:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:13 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:13 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:13 primo-plus volumio[1183]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 14:29:13 primo-plus volumio[1183]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: volumiokiosk-touch Engine version: 3 Transport: polling Total Clients: 6 Aug 28 14:29:14 primo-plus volumio[1183]: info: TidalConnect service started! Aug 28 14:29:14 primo-plus volumio[1183]: info: Completed starting Core Plugins Aug 28 14:29:14 primo-plus volumio[1183]: info: ------------------------------------------- Aug 28 14:29:14 primo-plus volumio[1183]: info: ----- MyVolumio plugins startup ---- Aug 28 14:29:14 primo-plus volumio[1183]: info: ------------------------------------------- Aug 28 14:29:14 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:14 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 14:29:14 primo-plus volumio[1183]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 28 14:29:14 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:14 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:14 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:14 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:14 primo-plus volumio[1183]: info: Listing playlists Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:14 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:14 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:14 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:14 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:14 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:14 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:14 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:16 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 28 14:29:16 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 14:29:16 primo-plus systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 28 14:29:16 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:16 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:16 primo-plus systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 28 14:29:16 primo-plus go-librespot[2311]: go-librespot daemon starting... Aug 28 14:29:16 primo-plus systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="app state loaded" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=info msg="zeroconf server listening on port 41549" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="obtained new client token: AAHqjf9niGGb6RbOFWpR5c8YNPAhyt8TWIdYQycrRLeicJZdCU6/Wa15JYaKYl4Qw/NZmpKR+PbSZoiGvRkWKUTTBZ7QsLwYT67W8kpEMicIy4Fw1wJFV/e09D2EJlwAOvWQsh3mT9j081dKmfxZ9eAC1JzNWcsZOFzqmJOHbn/He8uEDKYWdiHdnCPzHLZlt9ysozc6MiBJTWgsnUwoU+AHa2iPdu396pa0s7QRre6hdFmlVZewQSUsIQ==" Aug 28 14:29:16 primo-plus volumio[1183]: info: Executing endpoint metavolumio Aug 28 14:29:16 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=debug msg="completed challenge" Aug 28 14:29:16 primo-plus go-librespot[2312]: time="2026-08-28T14:29:16+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:17 primo-plus go-librespot[2312]: time="2026-08-28T14:29:17+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:17 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:17 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:17 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:17 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:18 primo-plus volumio[1183]: info: Checking for updated MCU Firmware Aug 28 14:29:18 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 14:29:18 primo-plus volumio[1183]: info: Firware on device is on latest version, no need to update Aug 28 14:29:20 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 14:29:20 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:20 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:20 primo-plus go-librespot[2322]: go-librespot daemon starting... Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="app state loaded" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.372+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.178.72:49155 Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.436+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.178.72:49155 @ 0x1801710" latency=29.593347ms timeout=20s Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.436+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.437+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.178.72:49155 @ 0x1801710" latency=29.527812ms platform=PLATFORM_IOS version=6.260722.0 Aug 28 14:29:20 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:20 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:20 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.443+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" name="Primo Plus" Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.447+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" language=it Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.450+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" timezone=Europe/Rome Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.451+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" available=true connected=false macAddress= ip4Address= ip6Address= Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.455+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" available=true connected=true macAddress=d8:3a:dd:ea:47:0d ip4Address=192.168.178.84/24 ip6Address= ssid="FRITZ!Box 5530 WB" Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.456+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" setupComplete=true Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 14:29:20 primo-plus volumio[1183]: amixer -c 0 info | grep "es9039q2m" Aug 28 14:29:20 primo-plus volumio[1183]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 28 14:29:20 primo-plus volumio[1183]: amixer -c 0 info | grep "es9039q2m" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:20 primo-plus volumio[1183]: Card sysdefault:0 'es9039q2m'/'es9039q2m' Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.530+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" selectedOutputId=0 Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=info msg="zeroconf server listening on port 38401" Aug 28 14:29:20 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:20 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:20 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.544+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" currentVersion=4.164 latestVersion=4.164 Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.544+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.178.72:49155 @ 0x1801710" status=UPDATE_STATUS_NONE progress=0 Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.544+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" userId= Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.545+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" providers=3 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.547+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" plugins=0 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:20 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.553+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" state=STATUS_STOPPED positionMs=0 volume=55 Aug 28 14:29:20 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:20.553+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.72:49155 @ 0x1801710" id=calmradio://4/488 title="AMBIENT THINGS" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="obtained new client token: AAEA8C+hawdvzD1RVt/lqOFzG0JZcbJqn6MJ5xlfVKQyfxD/DE5IGd5RDYQ7pLETciWnuPdO9q0ViaZtK1LrxENH3+udkyGKVl9ipGgXBzYPL2ImbHjPaC4gmPFblx1BNJJM2quZE06e6aJyx+8e1WpnrXRtq/q/qSdcsJTXUJnoqUJt310drt82gmmKqUPJnIOiwmCFuexFC3GhFNMGwWb8QdnCSTwEFs8+us7fCFEDNL0RqODMry9U8Q==" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=debug msg="completed challenge" Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:20 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:20 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:20 primo-plus volumio[1183]: verbose: New Socket.io Connection to 192.168.178.84:3000 from 192.168.178.72 UA: Dart/3.11 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 14:29:20 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 14:29:20 primo-plus go-librespot[2323]: time="2026-08-28T14:29:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:20 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:20 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:20 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:20 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 14:29:22 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 14:29:23 primo-plus volumio[1183]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 14:29:23 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 14:29:23 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:23 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:23 primo-plus volumio[1183]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 14:29:23 primo-plus volumio[1183]: info: MyVolumio login type: Token Aug 28 14:29:23 primo-plus volumio[1183]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 14:29:23 primo-plus volumio[1183]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' Aug 28 14:29:23 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 28 14:29:23 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:23.697+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.178.72:49155 @ 0x1801710" latency=21.263547ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 28 14:29:23 primo-plus volumio[1183]: error: MyVolumio Custom Token format not valid, refreshing it Aug 28 14:29:23 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:23 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:24 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 14:29:24 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:24 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:24 primo-plus go-librespot[2343]: go-librespot daemon starting... Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="app state loaded" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=info msg="zeroconf server listening on port 40441" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="obtained new client token: AAGFGTE4N0/S/ipPQrJ/6sClP8K0gygnU9kdnyD+UMrRwpbuJhjvMlUPFFA8Zqoz8sisVcUjobWlcqFU/iddFH6eLAeVugaAh3fncZxvLvLtmC+OlA3MG0kSDfD4wvDAoujHQy+mJYAOTAJa4yQSVpgeFRBFllJvFwyLnlmE5W736QfVsOxxieMA5uq8r7yI8zunBhccI8BtHxwSWpuCxpViUX2ED3JWGsUX+QFKdizUYbphFrh2KYNsAQ==" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Aug 28 14:29:24 primo-plus volumio[1183]: info: MyVolumio login type: Token Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=debug msg="completed challenge" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:24 primo-plus go-librespot[2344]: time="2026-08-28T14:29:24+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:24 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:24 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:24 primo-plus sudo[2369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 14:29:24 primo-plus sudo[2369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:24 primo-plus sudo[2371]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 14:29:24 primo-plus sudo[2371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:24 primo-plus sudo[2369]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:24 primo-plus sudo[2371]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:25 primo-plus volumio[1183]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 28 14:29:25 primo-plus volumio[1183]: verbose: New Socket.io Connection to 192.168.178.84 from 192.168.178.72 UA: Mozilla/5.0 (iPad; CPU OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Aug 28 14:29:25 primo-plus sudo[2376]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 14:29:25 primo-plus sudo[2376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:25 primo-plus sudo[2376]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:25 primo-plus sudo[2378]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 14:29:25 primo-plus sudo[2378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:25 primo-plus sudo[2378]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:25 primo-plus volumio[1183]: verbose: New Socket.io Connection to 192.168.178.84 from 192.168.178.72 UA: Mozilla/5.0 (iPad; CPU OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 14:29:25 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC, ...) Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:25 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 14:29:25 primo-plus volumio[1183]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Aug 28 14:29:25 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:25 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:25 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:25 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:25 primo-plus volumio[1183]: info: Listing playlists Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 14:29:25 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 14:29:25 primo-plus volumio[1183]: info: MyVolumio token set successfully Aug 28 14:29:25 primo-plus volumio[1183]: info: MYVOLUMIO: Adding device Aug 28 14:29:25 primo-plus volumio[1183]: info: MYVOLUMIO: Evaluating Server Aug 28 14:29:25 primo-plus volumio[1183]: info: MyVolumio Plan changed: premium Aug 28 14:29:25 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Aug 28 14:29:25 primo-plus volumio[1183]: info: Removing browser output: myVolumio user plan is not superstar Aug 28 14:29:25 primo-plus volumio[1183]: info: Removing audio output: Aug 28 14:29:25 primo-plus volumio[1183]: info: MYVOLUMIO: Adding device Aug 28 14:29:25 primo-plus volumio[1183]: info: MYVOLUMIO: Evaluating Server Aug 28 14:29:25 primo-plus volumio[1183]: info: Remote config written successfully Aug 28 14:29:25 primo-plus volumio[1183]: info: Starting Tunnel 1 Aug 28 14:29:25 primo-plus volumio[1183]: info: Starting Tunnel Connection Checker Aug 28 14:29:26 primo-plus volumio[1183]: info: MYVolumio Device enabled Aug 28 14:29:26 primo-plus volumio[1183]: info: MyVolumio status changed Aug 28 14:29:26 primo-plus volumio[1183]: info: Streaming services startup Aug 28 14:29:26 primo-plus volumio[1183]: info: Starting Streaming Daemon Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Aug 28 14:29:26 primo-plus sudo[2421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 14:29:26 primo-plus sudo[2421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:26 primo-plus volumio[1183]: info: Setting Geolocation for MyVolumio to eu11 Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 28 14:29:26 primo-plus volumio[1183]: error: [MyVolumio PluginManager] Cache data is invalid! Aug 28 14:29:26 primo-plus sudo[2421]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:26 primo-plus volumio[1183]: error: Cannot start Volumio Streaming Daemon Aug 28 14:29:26 primo-plus volumio[1183]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 14:29:26 primo-plus volumio[1183]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 14:29:26 primo-plus volumio[1183]: info: Successfully Added MyVolumio device Aug 28 14:29:26 primo-plus volumio[1183]: info: Setting Geolocation for MyVolumio to eu4 Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:26 primo-plus volumio5-onboarding[1995]: time=2026-08-28T14:29:26.605+02:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin audio_interface/bluetooth is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin audio_interface/multiroom is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin miscellanea/metavolumio is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin miscellanea/manifestui is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/cd_controller is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/smart_inputs is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/hi_res_audio is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/tidal is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/qobuz is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/tidalconnect is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: [MyVolumio PluginManager] Plugin music_service/qobuzconnect is enabled for this plan, but could not be found on the local filesystem! Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 28 14:29:26 primo-plus dbus-daemon[739]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.22" (uid=0 pid=1995 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=922 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 28 14:29:26 primo-plus volumio[1183]: info: Successfully Added MyVolumio device Aug 28 14:29:26 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 28 14:29:26 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:26 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0001, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0001/char0002, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0001/char0004, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0006, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0006/char0007, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0006/char0007/desc0009, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000a, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000a/char000b, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000a/char000d, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000f, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000f/char0010, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000f/char0010/desc0012, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service000f/char0010/desc0013, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0014, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0014/char0015, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0014/char0015/desc0017, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0014/char0015/desc0018, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0019, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0019/char001a, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0019/char001a/desc001c, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service001d, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service001d/char001e, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service001d/char001e/desc0020, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service001d/char0021, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char0024, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char0024/desc0026, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char0027, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char0027/desc0029, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char002a, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service0023/char002a/desc002c, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char002e, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char002e/desc0030, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char002e/desc0031, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char0032, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char0032/desc0034, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char0032/desc0035, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char0036, ...) Aug 28 14:29:27 primo-plus bluealsa[1011]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5A_0B_F1_74_1E_CC/service002d/char0036/desc0038, ...) Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:27 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:27 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:27 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:27 primo-plus volumio[1183]: info: Updating MyVolumio device info Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: Updating MyVolumio device info Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:27 primo-plus volumio[1183]: info: Successfully Updated MyVolumio device Aug 28 14:29:27 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 14:29:27 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:27 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:27 primo-plus go-librespot[2423]: go-librespot daemon starting... Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=debug msg="app state loaded" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:27 primo-plus volumio[1183]: info: Successfully Updated MyVolumio device Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=info msg="zeroconf server listening on port 41875" Aug 28 14:29:27 primo-plus go-librespot[2424]: time="2026-08-28T14:29:27+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=debug msg="obtained new client token: AAHxQG53gJU1q3qH7O+uSkL1byAJYGT4zEcgFftiqGrADnYU+Wp9mIkyzZlrEbL7x9C0COdVhXZE4ZcFJWiK+4xs/dOJY4oLoqGI7xoErT7MAtt3RQyqCkv5FCJKDShj7Ti74zyUjQmsXcUQ/9kobTKk9v/AFrYCsXzR3DOijz+PzSTzLzz80VH/A1bsZa+Ccz3pTEDr7Lmj/t2FWGsZrEM7jT5IF5rokW1k2im2W6MakyGIviMCsO8=" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=debug msg="completed challenge" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:28 primo-plus go-librespot[2424]: time="2026-08-28T14:29:28+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:28 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:28 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:28 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 14:29:28 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:28 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:28 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:28 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:28 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:28 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:28 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:29 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:29 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 14:29:30 primo-plus volumio[1183]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 28 14:29:30 primo-plus volumio[1183]: info: Received Get System Version Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 14:29:30 primo-plus volumio[1183]: info: Received Get System Info Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 14:29:30 primo-plus volumio[1183]: info: Discovery: Getting this device information Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:30 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:30 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 14:29:31 primo-plus sudo[2439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 28 14:29:31 primo-plus sudo[2439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:31 primo-plus systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 14:29:31 primo-plus systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 14:29:31 primo-plus systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 28 14:29:31 primo-plus sudo[2439]: pam_unix(sudo:session): session closed for user root Aug 28 14:29:31 primo-plus volumio[1183]: info: Remote SSH Started Aug 28 14:29:31 primo-plus autossh[2442]: port set to 0, monitoring disabled Aug 28 14:29:31 primo-plus autossh[2442]: starting ssh (count 1) Aug 28 14:29:31 primo-plus autossh[2442]: ssh child pid is 2445 Aug 28 14:29:31 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 28 14:29:31 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:31 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:31 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 28 14:29:31 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:31 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:31 primo-plus go-librespot[2446]: go-librespot daemon starting... Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="app state loaded" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=info msg="zeroconf server listening on port 38573" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="obtained new client token: AAEYc27urRhAXOx2rZb8OQ4ZJqtI+78iUgRR+VH7gfTi15qh4Sl97HGgpeuUSAKoomjJpaqKQeSbwRdLIO6cUuRLQQF8epYDymkxdZuKNogz6CX3u5a6qXxTFXcxw8ooNK4NBAAJsltJyQbL8LKtL9y65d/vR10wdHI9DMKHrmYfP8WE/ZogDLoCFfbqZRvsDrW47zyKEkwAW7+hSp+CkJzxT7Y4XOZbPwW6+4eEeDHd+8Eu2Wrf2iFWAQ==" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=debug msg="completed challenge" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:31 primo-plus go-librespot[2447]: time="2026-08-28T14:29:31+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:31 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:31 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:32 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetQueue Aug 28 14:29:32 primo-plus volumio[1183]: info: CoreStateMachine::getQueue Aug 28 14:29:32 primo-plus volumio[1183]: info: CorePlayQueue::getQueue Aug 28 14:29:32 primo-plus volumiossh-tunnel[2445]: Warning: Permanently added '[eu4.myvolumio.org]:2222' (RSA) to the list of known hosts. Aug 28 14:29:32 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:32 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:34 primo-plus volumio[1183]: error: MyVolumio Plugin failed to start in a timely fashion Aug 28 14:29:34 primo-plus volumio[1183]: [Metrics] CommandRouter: 52s 343.93ms Aug 28 14:29:34 primo-plus volumio[1183]: info: CoreCommandRouter::volumiosetStartupVolume Aug 28 14:29:34 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:34 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:34 primo-plus volumio[1183]: info: CoreCommandRouter::Close All Modals sent Aug 28 14:29:34 primo-plus volumio[1183]: info: CoreCommandRouter::Close All Modals sent Aug 28 14:29:34 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 28 14:29:34 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:34 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:34 primo-plus go-librespot[2458]: go-librespot daemon starting... Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=debug msg="app state loaded" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=info msg="zeroconf server listening on port 40229" Aug 28 14:29:34 primo-plus go-librespot[2459]: time="2026-08-28T14:29:34+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=debug msg="obtained new client token: AAGoJ+QW1yfK6pQBoQKnQkf4jFmP7K22VCjPiOMX9Zft6TfHeB6Ovr10iASQLUgoGMv+vMUoWT/tN25Y61BO/4LaGbKkSiCJcyod1pNPlcFAxrVt6LIMuqpTw6d0lxSaZV16B32MtknA/Lzb+ZL6exhftoos1idP75enfxTvSAcpgj1Cz0eYQ1LLVVs9lsdBKP9+2VpHKu5NGNsG5NQMPdUrkfJ5XsuJbwZ4svwFbg2coIDHJVMRWUQ=" Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=debug msg="completed challenge" Aug 28 14:29:35 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 28 14:29:35 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 14:29:35 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:35 primo-plus go-librespot[2459]: time="2026-08-28T14:29:35+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:35 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:35 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:35 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 28 14:29:35 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:35 primo-plus volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 14:29:38 primo-plus volumio-remote-updater[757]: Test mode disabled Aug 28 14:29:38 primo-plus volumio-remote-updater[757]: Alpha mode disabled Aug 28 14:29:38 primo-plus volumio-remote-updater[757]: Alpha legacy test mode disabled Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 28 14:29:38 primo-plus volumio[1183]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 14:29:38 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 28 14:29:38 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:38 primo-plus volumio[1183]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Aug 28 14:29:38 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:38 primo-plus go-librespot[2489]: go-librespot daemon starting... Aug 28 14:29:38 primo-plus volumio[1183]: info: CoreCommandRouter::volumioGetState Aug 28 14:29:38 primo-plus volumio[1183]: info: CorePlayQueue::getTrack 0 Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="app state loaded" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=info msg="zeroconf server listening on port 40151" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="obtained new client token: AAEBpDsid0XBF5iJT6mDfkHgC0BKUO/ps72YQAMzqhja7RHjPh9F95rmoMwAkCFHj7Wm4F563QNsx+htiBqOynk9Mobqzf82tkMKw0pRXBRLIZMANwHOKyP3ywwYX+7iJVlcFzR9mbC0r5CydXxEMBWYCjan7mLBa1QkpRdk8jKeTeztb8anFIN7USl41goN/0HN2EhwDILTms7naVp+HH8VzSh+5Th0WUUdj//rZdNo0leuy+htwOdWYQ==" Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 28 14:29:38 primo-plus volumio[1183]: info: Initializing connection to go-librespot Websocket Aug 28 14:29:38 primo-plus go-librespot[2490]: time="2026-08-28T14:29:38+02:00" level=debug msg="new websocket client" Aug 28 14:29:38 primo-plus volumio[1183]: info: Connection to go-librespot Websocket established Aug 28 14:29:39 primo-plus go-librespot[2490]: time="2026-08-28T14:29:39+02:00" level=debug msg="completed keyexchange" Aug 28 14:29:39 primo-plus go-librespot[2490]: time="2026-08-28T14:29:39+02:00" level=debug msg="completed challenge" Aug 28 14:29:39 primo-plus go-librespot[2490]: time="2026-08-28T14:29:39+02:00" level=info msg="authenticated AP" username="en******io" Aug 28 14:29:39 primo-plus go-librespot[2490]: time="2026-08-28T14:29:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 14:29:39 primo-plus systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 14:29:39 primo-plus volumio[1183]: info: Connection to go-librespot Websocket closed Aug 28 14:29:39 primo-plus systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 14:29:41 primo-plus volumio[1183]: info: BOOT COMPLETED Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 14:29:41 primo-plus volumio[1183]: info: Not Reporting Auto name since its the default one Aug 28 14:29:41 primo-plus volumio[1183]: info: Getting Spotify volume Aug 28 14:29:42 primo-plus volumio[1183]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 14:29:42 primo-plus volumio[1183]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 14:29:42 primo-plus volumio[1183]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 14:29:42 primo-plus volumio[1183]: errno: -111, Aug 28 14:29:42 primo-plus volumio[1183]: code: 'ECONNREFUSED', Aug 28 14:29:42 primo-plus volumio[1183]: syscall: 'connect', Aug 28 14:29:42 primo-plus volumio[1183]: address: '127.0.0.1', Aug 28 14:29:42 primo-plus volumio[1183]: port: 9879, Aug 28 14:29:42 primo-plus volumio[1183]: response: undefined Aug 28 14:29:42 primo-plus volumio[1183]: } Aug 28 14:29:42 primo-plus volumio[1183]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 14:29:42 primo-plus systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 28 14:29:42 primo-plus systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:42 primo-plus systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 14:29:42 primo-plus go-librespot[2516]: go-librespot daemon starting... Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=debug msg="app state loaded" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 14:29:42 primo-plus sudo[2525]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 14:28' Aug 28 14:29:42 primo-plus sudo[2525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=info msg="zeroconf server listening on port 35001" Aug 28 14:29:42 primo-plus go-librespot[2517]: time="2026-08-28T14:29:42+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" 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"