Sep 10 09:21:45 volumio ntpd[820]: CLOCK: time stepped by 808785.093347 Sep 10 09:21:45 volumio ntpd[820]: CLOCK: time changed from 2025-09-01 to 2025-09-10 Sep 10 09:21:45 volumio ntpd[820]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: A device disappeared from network Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: Device volumio disappeared from network Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: A device disappeared from network Sep 10 09:21:45 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Sep 10 09:21:45 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Sep 10 09:21:45 volumio systemd[1]: Starting fstrim.service - Discard unused blocks on filesystems from /etc/fstab... Sep 10 09:21:45 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Sep 10 09:21:45 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Sep 10 09:21:45 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Sep 10 09:21:45 volumio volumio[1921]: info: Initializing connection to go-librespot Websocket Sep 10 09:21:45 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: A device disappeared from network Sep 10 09:21:45 volumio go-librespot[2381]: time="2025-09-10T09:21:45+02:00" level=debug msg="new websocket client" Sep 10 09:21:45 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Sep 10 09:21:45 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Sep 10 09:21:45 volumio volumio[1921]: info: Connection to go-librespot Websocket established Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: adding 50713a91-c451-4cdb-a360-60f41d0df4c9 Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: Found device Volumio Sep 10 09:21:45 volumio volumio[1921]: info: CoreCommandRouter::volumioGetState Sep 10 09:21:45 volumio volumio[1921]: info: CorePlayQueue::getTrack 0 Sep 10 09:21:45 volumio fstrim[2449]: /boot: 273.1 MiB (286330880 bytes) trimmed on /dev/mmcblk0p1 Sep 10 09:21:45 volumio systemd[1]: fstrim.service: Deactivated successfully. Sep 10 09:21:45 volumio systemd[1]: Finished fstrim.service - Discard unused blocks on filesystems from /etc/fstab. Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: this is already registered, 50713a91-c451-4cdb-a360-60f41d0df4c9 Sep 10 09:21:45 volumio volumio[1921]: info: Discovery: Found device Volumio Sep 10 09:21:45 volumio volumio[1921]: info: CoreCommandRouter::volumioGetState Sep 10 09:21:45 volumio volumio[1921]: info: CorePlayQueue::getTrack 0 Sep 10 09:21:46 volumio volumio[1921]: info: Discovery: this is already registered, 50713a91-c451-4cdb-a360-60f41d0df4c9 Sep 10 09:21:46 volumio volumio[1921]: info: Discovery: Found device Volumio Sep 10 09:21:46 volumio volumio[1921]: info: CoreCommandRouter::volumioGetState Sep 10 09:21:46 volumio volumio[1921]: info: CorePlayQueue::getTrack 0 Sep 10 09:21:48 volumio volumio[1921]: info: Getting Spotify volume Sep 10 09:21:48 volumio volumio[1921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 10 09:21:49 volumio volumio[1921]: info: CoreCommandRouter::volumioGetState Sep 10 09:21:49 volumio volumio[1921]: info: CorePlayQueue::getTrack 0 Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin bluetooth to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin multiroom to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin metavolumio to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin cd_controller to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 10 09:21:51 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 10 09:21:54 volumio volumio[1921]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 10 09:21:54 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 10 09:21:54 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:21:54 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:21:54 volumio volumio[1921]: info: Starting MyVolumio Remote Streaming Endpoints Sep 10 09:21:54 volumio volumio[1921]: info: MyVolumio login type: Token Sep 10 09:21:54 volumio volumio[1921]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 10 09:21:54 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 10 09:21:56 volumio volumio[1921]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 10 09:21:56 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 10 09:21:56 volumio volumio[1921]: info: Streaming services startup Sep 10 09:21:56 volumio volumio[1921]: info: Starting Streaming Daemon Sep 10 09:21:56 volumio volumio[1921]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 10 09:21:56 volumio sudo[2486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 10 09:21:56 volumio sudo[2486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:21:56 volumio sudo[2486]: pam_unix(sudo:session): session closed for user root Sep 10 09:21:56 volumio volumio[1921]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.022&uuid=8c3a06dd9480d1856618b73a042a67cf" http://updates.volumio.org/downloader-v1/track-device Sep 10 09:21:56 volumio volumio[1921]: % Total % Received % Xferd Average Speed Time Time Time Current Sep 10 09:21:56 volumio volumio[1921]: Dload Upload Total Spent Left Speed Sep 10 09:21:56 volumio volumio[1921]: [2.2K blob data] Sep 10 09:21:56 volumio volumio[1921]: retrying in 5 seconds, trial 0 Sep 10 09:21:56 volumio volumio[1921]: info: Volumio Calling Home Sep 10 09:21:56 volumio volumio[1921]: error: Cannot start Volumio Streaming Daemon Sep 10 09:21:56 volumio volumio[1921]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 10 09:21:56 volumio volumio[1921]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 10 09:21:56 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 10 09:21:56 volumio volumio[1921]: info: Volumio called home Sep 10 09:21:57 volumio volumio[1921]: error: MyVolumio Custom Token format not valid, refreshing it Sep 10 09:21:58 volumio volumio[1921]: info: MyVolumio login type: Token Sep 10 09:21:58 volumio volumio[1921]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Sep 10 09:21:59 volumio volumio[1921]: info: MyVolumio token set successfully Sep 10 09:21:59 volumio volumio[1921]: info: MYVOLUMIO: Adding device Sep 10 09:21:59 volumio volumio[1921]: info: MYVOLUMIO: Evaluating Server Sep 10 09:21:59 volumio volumio[1921]: info: MyVolumio Plan changed: premium Sep 10 09:21:59 volumio volumio[1921]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Sep 10 09:21:59 volumio volumio[1921]: info: Removing browser output: myVolumio user plan is not superstar Sep 10 09:22:00 volumio volumio[1921]: info: Removing audio output: Sep 10 09:22:00 volumio volumio[1921]: info: MYVOLUMIO: Adding device Sep 10 09:22:00 volumio volumio[1921]: info: MYVOLUMIO: Evaluating Server Sep 10 09:22:00 volumio volumio[1921]: info: Remote config written successfully Sep 10 09:22:00 volumio volumio[1921]: info: Starting Tunnel 1 Sep 10 09:22:00 volumio volumio[1921]: info: Starting Tunnel Connection Checker Sep 10 09:22:00 volumio volumio[1921]: info: MYVolumio Device enabled Sep 10 09:22:00 volumio volumio[1921]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Sep 10 09:22:00 volumio volumio[1921]: info: MyVolumio status changed Sep 10 09:22:00 volumio volumio[1921]: info: Streaming services startup Sep 10 09:22:00 volumio volumio[1921]: info: Starting Streaming Daemon Sep 10 09:22:00 volumio volumio[1921]: info: Setting Geolocation for MyVolumio to eu10 Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio sudo[2543]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 10 09:22:00 volumio sudo[2543]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:00 volumio sudo[2543]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:00 volumio volumio[1921]: error: Cannot start Volumio Streaming Daemon Sep 10 09:22:00 volumio volumio[1921]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 10 09:22:00 volumio volumio[1921]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 10 09:22:00 volumio volumio[1921]: info: Setting Geolocation for MyVolumio to eu7 Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:00 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Sep 10 09:22:00 volumio volumio[1921]: error: [MyVolumio PluginManager] Cache data is invalid! Sep 10 09:22:01 volumio volumio[1921]: info: Successfully Added MyVolumio device Sep 10 09:22:01 volumio volumio[1921]: info: Updating MyVolumio device info Sep 10 09:22:01 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:01 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:01 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:01 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Sep 10 09:22:02 volumio volumio[1921]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Sep 10 09:22:02 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Sep 10 09:22:04 volumio volumio[1921]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Sep 10 09:22:04 volumio sudo[2549]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Sep 10 09:22:04 volumio sudo[2549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:04 volumio sudo[2549]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:05 volumio volumio[1921]: info: MRS: MultiRoom plugin initialized Sep 10 09:22:05 volumio volumio[1921]: info: MRS: STOPPING SNAPCLIENT Sep 10 09:22:05 volumio volumio[1921]: info: MRS: Snap server stop Sep 10 09:22:05 volumio sudo[2566]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Sep 10 09:22:05 volumio sudo[2566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:05 volumio sudo[2568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Sep 10 09:22:05 volumio sudo[2568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:05 volumio sudo[2566]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:05 volumio sudo[2568]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:05 volumio volumio[1921]: info: MRS: STOPPING volumioStreaming Sep 10 09:22:05 volumio sudo[2572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Sep 10 09:22:05 volumio sudo[2572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:05 volumio sudo[2574]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Sep 10 09:22:05 volumio sudo[2574]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:05 volumio sudo[2574]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:05 volumio sudo[2572]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Sep 10 09:22:05 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Sep 10 09:22:06 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Sep 10 09:22:06 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Sep 10 09:22:06 volumio volumio[1921]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Sep 10 09:22:06 volumio volumio[1921]: info: Preparing to generate the ALSA configuration file Sep 10 09:22:06 volumio volumio[1921]: info: Updating MyVolumio device info Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Sep 10 09:22:06 volumio volumio[1921]: info: Successfully Added MyVolumio device Sep 10 09:22:06 volumio volumio[1921]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Sep 10 09:22:06 volumio volumio[1921]: info: Reading ALSA contributions from plugins. Sep 10 09:22:06 volumio volumio[1921]: info: MRS: Removed streaming files Sep 10 09:22:06 volumio volumio[1921]: info: MRS: volumioStreaming STOPPED Sep 10 09:22:06 volumio volumio[1921]: info: MRS: SNAPSERVER STOPPED Sep 10 09:22:06 volumio volumio[1921]: info: MRS: SNAPCLIENT STOPPED Sep 10 09:22:06 volumio volumio[1921]: info: Successfully Updated MyVolumio device Sep 10 09:22:06 volumio volumio[1921]: info: Successfully Updated MyVolumio device Sep 10 09:22:06 volumio volumio[1921]: info: Asound.conf file unchanged, so no further update is needed Sep 10 09:22:06 volumio volumio[1921]: info: Output device has changed, restarting MPD Sep 10 09:22:06 volumio sudo[2583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Sep 10 09:22:06 volumio sudo[2583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:06 volumio volumio[1921]: info: Output device has changed, restarting Shairport Sync Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 09:22:06 volumio sudo[2588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 10 09:22:06 volumio sudo[2588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:06 volumio volumio[1921]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 10 09:22:06 volumio volumio[1921]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Sep 10 09:22:06 volumio sudo[2588]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:06 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Sep 10 09:22:06 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Sep 10 09:22:06 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 09:22:07 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Sep 10 09:22:07 volumio volumio[1921]: ------------------------------------ BT MESSAGE: [FUNC] onStart Sep 10 09:22:07 volumio volumio[1921]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Sep 10 09:22:07 volumio systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Sep 10 09:22:07 volumio sudo[2590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 10 09:22:07 volumio sudo[2590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:07 volumio sudo[2583]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:07 volumio autossh[2600]: port set to 0, monitoring disabled Sep 10 09:22:07 volumio autossh[2600]: starting ssh (count 1) Sep 10 09:22:07 volumio autossh[2600]: ssh child pid is 2604 Sep 10 09:22:07 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Sep 10 09:22:07 volumio volumio[1921]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Sep 10 09:22:07 volumio volumio[1921]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Sep 10 09:22:07 volumio volumio[1921]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Sep 10 09:22:07 volumio systemd[1]: mpd.service: Deactivated successfully. Sep 10 09:22:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 10 09:22:07 volumio systemd[1]: mpd.service: Consumed 4.919s CPU time. Sep 10 09:22:07 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Sep 10 09:22:07 volumio systemd[1]: mpd.socket: Deactivated successfully. Sep 10 09:22:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 10 09:22:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 10 09:22:07 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Sep 10 09:22:07 volumio volumio[1921]: info: MRS: Pushing multiroomSync output for this device Sep 10 09:22:07 volumio volumio[1921]: info: MRS: Pushing multiroomSync output Sep 10 09:22:07 volumio volumio[1921]: info: Adding audio output: Sep 10 09:22:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 10 09:22:07 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Sep 10 09:22:07 volumio bluetoothd[834]: Path / reserved for Adv Monitor app :1.43 Sep 10 09:22:07 volumio volumiossh-tunnel[2604]: Warning: Permanently added '[eu7.myvolumio.org]:2222' (RSA) to the list of known hosts. Sep 10 09:22:07 volumio bluetoothd[834]: Adv Monitor app :1.43 disconnected from D-Bus Sep 10 09:22:07 volumio volumio[1921]: info: Adding audio output: Sep 10 09:22:07 volumio sudo[2608]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 10 09:22:07 volumio sudo[2608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 10 09:22:07 volumio sudo[2608]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:07 volumio volumio[1921]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Sep 10 09:22:07 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 09:22:07 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Sep 10 09:22:07 volumio volumio[1921]: info: Adding METAVOLUMIO REST API Endpoints Sep 10 09:22:07 volumio volumio[1921]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Sep 10 09:22:07 volumio volumio[1921]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Sep 10 09:22:07 volumio volumio[1921]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Sep 10 09:22:07 volumio volumio[1921]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Sep 10 09:22:07 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Sep 10 09:22:07 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Sep 10 09:22:07 volumio volumio[1921]: info: Preparing CD Folders Sep 10 09:22:07 volumio volumio[1921]: info: Adding CD REST API Endpoints Sep 10 09:22:07 volumio volumio[1921]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Sep 10 09:22:07 volumio volumio[1921]: info: Starting UDEV Watcher for CD Sep 10 09:22:07 volumio volumio[1921]: info: Detecting CD presence with UDEV Sep 10 09:22:07 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Sep 10 09:22:07 volumio go-librespot[2381]: time="2025-09-10T09:22:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" Sep 10 09:22:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 10 09:22:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 10 09:22:10 volumio mpd[2611]: 2025-09-10T09:22:10 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 10 09:22:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Sep 10 09:22:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 10 09:22:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 10 09:22:10 volumio go-librespot[2631]: go-librespot daemon starting... Sep 10 09:22:10 volumio systemd[1]: Started mpd.service - Music Player Daemon. Sep 10 09:22:10 volumio sudo[2590]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:10 volumio go-librespot[2634]: time="2025-09-10T09:22:10+02:00" level=info msg="running go-librespot 0.3.2" Sep 10 09:22:10 volumio go-librespot[2634]: time="2025-09-10T09:22:10+02:00" level=debug msg="app state loaded" Sep 10 09:22:10 volumio go-librespot[2634]: time="2025-09-10T09:22:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+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]" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+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]" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+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]" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=info msg="zeroconf server listening on port 45151" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="obtained new client token: AADRm9q5hO4i6zgk3/XTQ8lOaINTpWcYcYXMRW2m8HQIdU7DXIUgsPPUeDH7YCbIc6jPQKb5jLY2WSSpgHYc+f2h7jYJwHUQWajYn85Y9nxbQJxAe2MJMxmwv9NxUqHUKwBMhtMAY1wyu+viqIUj8DB3CB4jMFurbJogwGWdaSZPpvKF8iZZk5ZLD+d71GNWF5pJO5+Pk8ltDM0rdfsLt7SbQEn1bboFGwy8XvnrKbqoIL+zC9kb016T4Q==" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="completed keyexchange" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="completed challenge" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=info msg="authenticated AP" username="5w*********************4l" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=info msg="authenticated Login5" username="5w*********************4l" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="initializing zeroconf session" username="5w*********************4l" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="dealer connection opened" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=trace msg="starting accesspoint recv loop" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=trace msg="starting dealer recv loop" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=trace msg="received accesspoint ping" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=debug msg="received connection id: NmMyMDI1YmItMGQy...OEVGQjQwM0ZDOA==" Sep 10 09:22:11 volumio go-librespot[2634]: time="2025-09-10T09:22:11+02:00" level=trace msg="received accesspoint pong ack" Sep 10 09:22:12 volumio go-librespot[2634]: time="2025-09-10T09:22:12+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 10 09:22:12 volumio go-librespot[2634]: time="2025-09-10T09:22:12+02:00" level=debug msg="update volume requested to 65535/65535" Sep 10 09:22:12 volumio go-librespot[2634]: time="2025-09-10T09:22:12+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 10 09:22:12 volumio go-librespot[2634]: time="2025-09-10T09:22:12+02:00" level=trace msg="emitting websocket event: volume" Sep 10 09:22:12 volumio volumio[1921]: warn: [cd-plugin] cdspeedctl: device or media not ready Sep 10 09:22:12 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Sep 10 09:22:12 volumio volumio[1921]: info: Adding inputs REST Endpoints Sep 10 09:22:12 volumio volumio[1921]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Sep 10 09:22:12 volumio volumio[1921]: info: Scanning Audio Inputs Sep 10 09:22:12 volumio volumio[1921]: info: Checking against Known Cards name Sep 10 09:22:12 volumio volumio[1921]: info: Checking against Known Cards name Sep 10 09:22:12 volumio volumio[1921]: info: Adding Server instance for streaming Sep 10 09:22:12 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Sep 10 09:22:12 volumio volumio[1921]: error: Hi Res Audio Failed Login: Missing Login Data Sep 10 09:22:12 volumio volumio[1921]: info: Adding HIGHRESAUDIO REST API Endpoints Sep 10 09:22:12 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Sep 10 09:22:12 volumio volumio[1921]: info: Refreshing TIDAL token Sep 10 09:22:12 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Sep 10 09:22:12 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Sep 10 09:22:13 volumio volumio[1921]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Sep 10 09:22:13 volumio volumio[1921]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Sep 10 09:22:13 volumio sudo[2646]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Sep 10 09:22:13 volumio sudo[2646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:13 volumio volumio[1921]: info: QobuzConnect: Starting Qobuz Connect socket and service Sep 10 09:22:13 volumio sudo[2646]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:13 volumio sudo[2653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Sep 10 09:22:13 volumio sudo[2653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:13 volumio volumio[1921]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Sep 10 09:22:13 volumio volumio[1921]: info: Stopping AccessToken refresher cron for QOBUZ Sep 10 09:22:13 volumio sudo[2653]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:13 volumio sudo[2656]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Sep 10 09:22:13 volumio sudo[2656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 10 09:22:13 volumio systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Sep 10 09:22:13 volumio sudo[2656]: pam_unix(sudo:session): session closed for user root Sep 10 09:22:13 volumio volumio[1921]: info: AccessToken refresher cron started for QOBUZ Sep 10 09:22:13 volumio volumio[1921]: info: Adding QOBUZ REST API Endpoints Sep 10 09:22:13 volumio volumio[1921]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 10 09:22:13 volumio volumio[1921]: info: MRS: Getting audio outputs on start Sep 10 09:22:13 volumio volumio[1921]: info: MRS: Requesting all other devices output Sep 10 09:22:13 volumio volumio[1921]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 09:22:14 volumio volumio[1921]: Error: socket hang up Sep 10 09:22:14 volumio volumio[1921]: at connResetException (node:internal/errors:720:14) Sep 10 09:22:14 volumio volumio[1921]: at Socket.socketOnEnd (node:_http_client:519:23) Sep 10 09:22:14 volumio volumio[1921]: at Socket.emit (node:events:526:35) Sep 10 09:22:14 volumio volumio[1921]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 10 09:22:14 volumio volumio[1921]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Sep 10 09:22:14 volumio volumio[1921]: code: 'ECONNRESET', Sep 10 09:22:14 volumio volumio[1921]: response: undefined Sep 10 09:22:14 volumio volumio[1921]: } Sep 10 09:22:14 volumio volumio[1921]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 09:22:17 volumio sudo[2673]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-10 09:21' Sep 10 09:22:17 volumio sudo[2673]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dfc7bb04e09bf2260691765a2340814af1fa2971" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="30d63a8c53d2826bd7f262e22b4e4511a4cc9d01" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Aug 30 06:39:32 UTC 2025" VOLUMIO_VERSION="4.022" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e7b0bd0cb5661ea77402e5bd121ec64a"