-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Fri 2025-12-26 15:40:40 CET. -- Dec 26 15:39:00 volumio dhcpcd[911]: wlan0: leased 192.168.50.24 for 86400 seconds Dec 26 15:39:00 volumio avahi-daemon[629]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.24. Dec 26 15:39:00 volumio avahi-daemon[629]: New relevant interface wlan0.IPv4 for mDNS. Dec 26 15:39:00 volumio avahi-daemon[629]: Registering new address record for 192.168.50.24 on wlan0.IPv4. Dec 26 15:39:00 volumio dhcpcd[911]: wlan0: adding route to 192.168.50.0/24 Dec 26 15:39:00 volumio dhcpcd[911]: wlan0: adding default route via 192.168.50.1 Dec 26 15:39:00 volumio wireless.js[621]: trying... Dec 26 15:39:00 volumio sudo[989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 26 15:39:00 volumio sudo[989]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:00 volumio sudo[989]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:00 volumio wireless.js[621]: Connected to: ----NAD Dec 26 15:39:00 volumio wireless.js[621]: ---- Dec 26 15:39:00 volumio sudo[992]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 15:39:00 volumio sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:00 volumio sudo[992]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:00 volumio wireless.js[621]: ... joined AP, wlan0 IPv4 is 192.168.50.24, ipV6 is undefined Dec 26 15:39:00 volumio wireless.js[621]: It's done! AP Dec 26 15:39:00 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 26 15:39:00 volumio systemd[1]: Started Wireless Services. Dec 26 15:39:00 volumio systemd[1]: Started Volumio Backend Module. Dec 26 15:39:00 volumio systemd[1]: Started Volumio Cpu Tweaker. Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: Setting RT Priority for mpd Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: Setting MPD Affinity Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: pid 813's current affinity mask: f Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: pid 813's new affinity mask: 3 Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Dec 26 15:39:00 volumio volumio-cpu-tweak[998]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Dec 26 15:39:00 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Dec 26 15:39:01 volumio ntpd[769]: Listen normally on 3 wlan0 192.168.50.24:123 Dec 26 15:39:01 volumio ntpd[769]: new interface(s) found: waking up resolver Dec 26 15:39:02 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:02 volumio volumio[997]: info: ----- Volumio3 ---- Dec 26 15:39:02 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:02 volumio volumio[997]: info: ----- System startup ---- Dec 26 15:39:02 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:03 volumio volumio[997]: info: MYVOLUMIO Environment detected Dec 26 15:39:03 volumio volumio[997]: info: Plugin folders cleanup Dec 26 15:39:03 volumio volumio[997]: info: Scanning into folder /volumio/app/plugins/ Dec 26 15:39:03 volumio volumio[997]: info: Scanning category audio_interface Dec 26 15:39:03 volumio volumio[997]: info: Scanning category miscellanea Dec 26 15:39:03 volumio volumio[997]: info: Scanning category music_service Dec 26 15:39:03 volumio volumio[997]: info: Scanning category plugins.json Dec 26 15:39:03 volumio volumio[997]: info: Scanning category system_controller Dec 26 15:39:03 volumio volumio[997]: info: Scanning category user_interface Dec 26 15:39:03 volumio volumio[997]: info: Scanning into folder /data/plugins/ Dec 26 15:39:03 volumio volumio[997]: info: Scanning category audio_interface Dec 26 15:39:03 volumio volumio[997]: info: Scanning category music_service Dec 26 15:39:03 volumio volumio[997]: info: Scanning category user_interface Dec 26 15:39:03 volumio volumio[997]: info: Plugin folders cleanup completed Dec 26 15:39:03 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:03 volumio volumio[997]: info: ----- Core plugins startup ---- Dec 26 15:39:03 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:03 volumio volumio[997]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 15:39:03 volumio volumio[997]: info: Adding plugin upnp to MyMusic Plugins Dec 26 15:39:03 volumio volumio[997]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 15:39:03 volumio volumio[997]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 15:39:03 volumio volumio[997]: info: Loading plugins from folder /data/plugins/ Dec 26 15:39:03 volumio volumio[997]: info: Loading plugin "system"... Dec 26 15:39:03 volumio volumio[997]: info: Loading plugin "appearance"... Dec 26 15:39:03 volumio volumio-time-update[632]: volumio-time-update-util: Fetching time from Volumio... Dec 26 15:39:03 volumio volumio-time-update[632]: volumio-time-update-util: Setting system time to: 2025-12-26 15:39:31 Dec 26 15:39:03 volumio sudo[1032]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-12-26 15:39:31 Dec 26 15:39:03 volumio sudo[1032]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:03 volumio dbus-daemon[617]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1033 comm="timedatectl set-time 2025-12-26 15:39:31 ") Dec 26 15:39:03 volumio systemd[1]: Starting Time & Date Service... Dec 26 15:39:03 volumio dbus-daemon[617]: [system] Successfully activated service 'org.freedesktop.timedate1' Dec 26 15:39:03 volumio systemd[1]: Started Time & Date Service. Dec 26 15:39:31 volumio systemd-timedated[1034]: Changed local time to Fri Dec 26 15:39:31 2025 Dec 26 15:39:31 volumio sudo[1032]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:31 volumio volumio-time-update[632]: volumio-time-update-util: System time updated successfully. Dec 26 15:39:31 volumio systemd[1]: Started Volumio Time Update Utility. Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "network"... Dec 26 15:39:31 volumio volumio[997]: info: Refreshing Cached IP Addresses Dec 26 15:39:31 volumio sudo[1036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 15:39:31 volumio sudo[1036]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:31 volumio sudo[1036]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:31 volumio sudo[1038]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 15:39:31 volumio sudo[1038]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:31 volumio sudo[1038]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "services"... Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "alsa_controller"... Dec 26 15:39:31 volumio sudo[1051]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 15:39:31 volumio sudo[1051]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:31 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "wizard"... Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "networkfs"... Dec 26 15:39:31 volumio volumio[997]: info: Starting Udev Watcher for removable devices Dec 26 15:39:31 volumio volumio[997]: info: Ignoring mount for partition: boot Dec 26 15:39:31 volumio volumio[997]: info: Ignoring mount for partition: volumio Dec 26 15:39:31 volumio volumio[997]: info: Ignoring mount for partition: volumio_data Dec 26 15:39:31 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "volumio_command_line_client"... Dec 26 15:39:31 volumio nmbd[735]: [2025/12/26 15:39:31.483732, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 26 15:39:31 volumio nmbd[735]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Dec 26 15:39:31 volumio systemd[1]: Started Samba NMB Daemon. Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "upnp"... Dec 26 15:39:31 volumio volumio[997]: info: [1766759971494] Starting Upmpd Daemon Dec 26 15:39:31 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "my_music"... Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "mpd"... Dec 26 15:39:31 volumio systemd[1]: Starting Samba Winbind Daemon... Dec 26 15:39:31 volumio winbindd[1063]: [2025/12/26 15:39:31.737357, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Dec 26 15:39:31 volumio winbindd[1063]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Dec 26 15:39:31 volumio winbindd[1063]: [2025/12/26 15:39:31.763397, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 26 15:39:31 volumio systemd[1]: Started Samba Winbind Daemon. Dec 26 15:39:31 volumio winbindd[1063]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Dec 26 15:39:31 volumio systemd[1]: Starting Samba SMB Daemon... Dec 26 15:39:31 volumio volumio[997]: info: Loading plugin "upnp_browser"... Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "alarm-clock"... Dec 26 15:39:32 volumio winbindd[1063]: [2025/12/26 15:39:32.190864, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Dec 26 15:39:32 volumio winbindd[1063]: res_names->count = 3, expected 4 Dec 26 15:39:32 volumio smbd[1068]: [2025/12/26 15:39:32.209038, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 26 15:39:32 volumio systemd[1]: Started Samba SMB Daemon. Dec 26 15:39:32 volumio smbd[1068]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Dec 26 15:39:32 volumio systemd[1]: Reached target Multi-User System. Dec 26 15:39:32 volumio systemd[1]: Reached target Graphical Interface. Dec 26 15:39:32 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 26 15:39:32 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 26 15:39:32 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 26 15:39:32 volumio systemd[1]: Startup finished in 12.331s (kernel) + 26.087s (userspace) = 38.419s. Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "airplay_emulation"... Dec 26 15:39:32 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "last_100"... Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "webradio"... Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "i2s_dacs"... Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "volumiodiscovery"... Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** For more information see Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 15:39:32 volumio node[997]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 15:39:32 volumio volumio[997]: *** WARNING *** For more information see Dec 26 15:39:32 volumio node[997]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 15:39:32 volumio node[997]: *** WARNING *** For more information see Dec 26 15:39:32 volumio node[997]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 15:39:32 volumio node[997]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 15:39:32 volumio node[997]: *** WARNING *** For more information see Dec 26 15:39:32 volumio volumio[997]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 15:39:32 volumio volumio[997]: info: Discovery: Started advertising with name: Volumio Dec 26 15:39:32 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 15:39:32 volumio volumio[997]: info: Loading plugin "spop"... Dec 26 15:39:32 volumio volumio-remote-updater[608]: [2025-12-26 15:39:32] [connect] Successful connection Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "outputs"... Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "albumart"... Dec 26 15:39:33 volumio volumio[997]: info: Plugin example_plugin is not enabled Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "inputs"... Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "updater_comm"... Dec 26 15:39:33 volumio volumio[997]: info: Plugin mpdemulation is not enabled Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "rest_api"... Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "websocket"... Dec 26 15:39:33 volumio volumio[997]: info: Starting Socket.io Server version 2.3.0 Dec 26 15:39:33 volumio volumio[997]: info: Plugin fusiondsp is not enabled Dec 26 15:39:33 volumio volumio[997]: info: Loading plugin "Systeminfo"... Dec 26 15:39:33 volumio volumio[997]: Forking 3 albumart workers Dec 26 15:39:34 volumio volumio[997]: info: Loading plugin "touch_display"... Dec 26 15:39:34 volumio volumio[997]: Starting albumart workers Dec 26 15:39:34 volumio volumio[997]: Starting albumart workers Dec 26 15:39:34 volumio volumio[997]: Starting albumart workers Dec 26 15:39:34 volumio volumio[997]: info: Applying required configuration parameters for plugin touch_display Dec 26 15:39:34 volumio volumio[997]: info: Loading i18n strings for locale en Dec 26 15:39:34 volumio volumio[997]: Updating browse sources language Dec 26 15:39:34 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:35 volumio sudo[1051]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::initPlayerControls Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 15:39:35 volumio volumio[997]: Express server listening on port 3000 Dec 26 15:39:35 volumio volumio[997]: [Metrics] WebUI: 6s 251.11ms Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::resetVolumioState Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::getcurrentVolume Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 15:39:35 volumio volumio[997]: info: Volumio Network Manager: Network status updated: 2 Dec 26 15:39:35 volumio volumio[997]: verbose: New Socket.io Connection to 192.168.50.24 from 192.168.50.22 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Dec 26 15:39:35 volumio volumio-remote-updater[608]: [2025-12-26 15:39:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1766759972 101 Dec 26 15:39:35 volumio volumio[997]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 2 Dec 26 15:39:35 volumio volumio[997]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: Reloading queue from file Dec 26 15:39:35 volumio volumio[997]: info: VolumeController:: Volume=44 Mute =false Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:39:35 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::updateTrackBlock Dec 26 15:39:35 volumio volumio[997]: info: CorePlayQueue::getTrackBlock Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::setRepeat null single undefined Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:39:35 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::setRandom null Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:39:35 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:39:35 volumio volumio[997]: info: Setting Device type: Raspberry PI Dec 26 15:39:35 volumio volumio[997]: info: Completed loading Core Plugins Dec 26 15:39:35 volumio volumio[997]: info: Preparing to generate the ALSA configuration file Dec 26 15:39:35 volumio volumio[997]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 26 15:39:35 volumio volumio[997]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Dec 26 15:39:35 volumio volumio[997]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 26 15:39:35 volumio volumio[997]: info: VolumeController:: Volume=44 Mute =false Dec 26 15:39:35 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:39:35 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:39:35 volumio volumio[997]: info: Asound.conf file unchanged, so no further update is needed Dec 26 15:39:35 volumio volumio[997]: info: Output device has changed, restarting MPD Dec 26 15:39:35 volumio sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 15:39:35 volumio sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio volumio[997]: info: Output device has changed, restarting Shairport Sync Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:35 volumio sudo[1147]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:35 volumio sudo[1149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 15:39:35 volumio sudo[1149]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio systemd[1]: Stopping Music Player Daemon... Dec 26 15:39:35 volumio volumio[997]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 15:39:35 volumio volumio[997]: info: ___________ START PLUGINS ___________ Dec 26 15:39:35 volumio volumio[997]: info: ControllerMpd::onStart: Initializing MPD Dec 26 15:39:35 volumio volumio[997]: info: Creating MPD Configuration file Dec 26 15:39:35 volumio sudo[1156]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 15:39:35 volumio sudo[1156]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 15:39:35 volumio volumio[997]: info: [1766759975643] CoreMusicLibrary::Adding element Media Servers Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:35 volumio sudo[1156]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:35 volumio sudo[1159]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 15:39:35 volumio sudo[1159]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:35 volumio systemd[1]: mpd.service: Succeeded. Dec 26 15:39:35 volumio systemd[1]: Stopped Music Player Daemon. Dec 26 15:39:35 volumio volumio[997]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 15:39:35 volumio volumio[997]: info: [1766759975732] CoreMusicLibrary::Adding element Last_100 Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 15:39:35 volumio volumio[997]: info: [1766759975734] CoreMusicLibrary::Adding element Webradio Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:35 volumio systemd[1]: Starting Music Player Daemon... Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:39:35 volumio volumio[997]: info: Initializing BBC Radios Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:35 volumio sudo[1164]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 15:39:35 volumio sudo[1164]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio volumio[997]: info: Creating Spotify config file Dec 26 15:39:35 volumio sudo[1164]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:35 volumio volumio[997]: info: Loading i18n strings for locale en Dec 26 15:39:35 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:39:35 volumio volumio[997]: info: Volumio Calling Home Dec 26 15:39:35 volumio sudo[1184]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Dec 26 15:39:35 volumio sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio sudo[1186]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Dec 26 15:39:35 volumio sudo[1186]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:35 volumio sudo[1189]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 26 15:39:35 volumio sudo[1189]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio volumio[997]: info: Discovery: adding f65ad322-ef24-46a8-96ad-94de724215fa Dec 26 15:39:36 volumio volumio[997]: info: Discovery: Found device Volumio Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:36 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:36 volumio volumio[997]: error: touch_display: Error detecting backlight interface: Error: ENOENT: no such file or directory, scandir '/sys/class/backlight/' Dec 26 15:39:36 volumio systemd[1]: Reloading. Dec 26 15:39:36 volumio volumio[997]: info: MPD Permissions set Dec 26 15:39:36 volumio volumio[997]: info: Spotify config file written Dec 26 15:39:36 volumio sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 15:39:36 volumio sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio sudo[1193]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio sudo[1202]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 15:39:36 volumio sudo[1202]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio sudo[1202]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 15:39:36 volumio volumio[997]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 26 15:39:36 volumio sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:39:36 volumio volumio[997]: info: No need to fix Spotify hosts Dec 26 15:39:36 volumio volumio[997]: info: Volumio called home Dec 26 15:39:36 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Dec 26 15:39:36 volumio volumio[997]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Dec 26 15:39:36 volumio sudo[1223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Dec 26 15:39:36 volumio sudo[1223]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio sudo[1223]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:39:36 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:39:36 volumio sudo[1226]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 15:39:36 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:39:36 volumio sudo[1226]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 15:39:36 volumio sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:36 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:36 volumio sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 15:39:36 volumio sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio volumio[997]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Dec 26 15:39:36 volumio volumio[997]: verbose: New Socket.io Connection to 192.168.50.24 from 192.168.50.22 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 15:39:36 volumio systemd[1]: ifup@eth0.service: Current command vanished from the unit file, execution of the command list won't be resumed. Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetVisibleSources Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:36 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 26 15:39:36 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:36 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:36 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:36 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:36 volumio volumio[997]: info: Listing playlists Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 26 15:39:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 15:39:36 volumio sudo[1189]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio sudo[1184]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio volumio[997]: info: touch_display: systemctl daemon-reload succeeded. Dec 26 15:39:36 volumio volumio[997]: info: touch_display: systemctl stop getty@tty1.service succeeded. Dec 26 15:39:36 volumio sudo[1235]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Dec 26 15:39:36 volumio sudo[1235]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:36 volumio mpd[1179]: Dec 26 15:39 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 15:39:36 volumio systemd[1]: Started Music Player Daemon. Dec 26 15:39:36 volumio sudo[1159]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio sudo[1149]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:36 volumio systemd[1]: Reloading. Dec 26 15:39:36 volumio volumio[997]: error: MPD error: The expression evaluated to a falsy value: Dec 26 15:39:36 volumio volumio[997]: assert.ok(self.idling) Dec 26 15:39:36 volumio volumio[997]: error: The expression evaluated to a falsy value: Dec 26 15:39:36 volumio volumio[997]: assert.ok(self.idling) Dec 26 15:39:36 volumio volumio[997]: error: updateQueue error: null Dec 26 15:39:36 volumio volumio[997]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 26 15:39:36 volumio volumio[997]: SPOTIFY: BQC8PxRaKYtIy9LfrvoXFYiInI2kCCLnM3zDSMREsduPBT14PhaVfR3HVSTeI9amomykSv7_6jFhbllfAK6nDOg9dIPufOJ9YrOz_zseXLyMRHBQR6-0krAv4HZsr75y1dXsuYdTOvz-PmXbjvzl_CuCgZNekX--zQya2p0RYYko_xqJesCsX2HT1RfOlwmCtaRAeTvfMIhdqB3N0TUsdZIqVSe44dL24H3FJYeI9AavY5O9X_oZP9a6iFyDdrONdy84K8GrL2YV3oB-0r19egegOpjmRuUr6Kp6PTsry3UrGWWfy7UslPdL Dec 26 15:39:36 volumio volumio[997]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 26 15:39:36 volumio volumio[997]: info: New Spotify access token = BQC8PxRaKYtIy9LfrvoXFYiInI2kCCLnM3zDSMREsduPBT14PhaVfR3HVSTeI9amomykSv7_6jFhbllfAK6nDOg9dIPufOJ9YrOz_zseXLyMRHBQR6-0krAv4HZsr75y1dXsuYdTOvz-PmXbjvzl_CuCgZNekX--zQya2p0RYYko_xqJesCsX2HT1RfOlwmCtaRAeTvfMIhdqB3N0TUsdZIqVSe44dL24H3FJYeI9AavY5O9X_oZP9a6iFyDdrONdy84K8GrL2YV3oB-0r19egegOpjmRuUr6Kp6PTsry3UrGWWfy7UslPdL Dec 26 15:39:36 volumio volumio[997]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 26 15:39:36 volumio volumio[997]: info: MPD running with PID1179 Dec 26 15:39:36 volumio volumio[997]: ,establishing connection Dec 26 15:39:36 volumio volumio[997]: error: updateQueue error: null Dec 26 15:39:36 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Dec 26 15:39:37 volumio volumio[997]: SPOTIFY: User informations: {"country":"HU","display_name":"Monika.beszedes","email":"monika.beszedes@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/xok0t4nib8hhzce2jwxq3z389"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/xok0t4nib8hhzce2jwxq3z389","id":"xok0t4nib8hhzce2jwxq3z389","images":[],"product":"premium","type":"user","uri":"spotify:user:xok0t4nib8hhzce2jwxq3z389"} Dec 26 15:39:37 volumio volumio[997]: info: Spotify Successfully logged in Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 15:39:37 volumio volumio[997]: info: [1766759977174] CoreMusicLibrary::Adding element Spotify Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:37 volumio volumio[997]: Cannot find translation for source Spotify Dec 26 15:39:37 volumio sudo[1186]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio volumio[997]: info: touch_display: systemctl disable getty@tty1.service succeeded. Dec 26 15:39:37 volumio systemd[1]: Started Volumio Kiosk. Dec 26 15:39:37 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 26 15:39:37 volumio sudo[1235]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio systemd[1]: Started go-librespot Daemon. Dec 26 15:39:37 volumio sudo[1212]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio systemd[1]: shairport-sync.service: Succeeded. Dec 26 15:39:37 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 26 15:39:37 volumio go-librespot[1256]: go-librespot daemon starting... Dec 26 15:39:37 volumio volumio[997]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Dec 26 15:39:37 volumio volumio[997]: info: touch_display: Volumio Kiosk started. Dec 26 15:39:37 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:37 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:37 volumio sudo[1226]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio sudo[1228]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio volumio[997]: info: Completed starting Core Plugins Dec 26 15:39:37 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:37 volumio volumio[997]: info: ----- MyVolumio plugins startup ---- Dec 26 15:39:37 volumio sudo[1231]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:37 volumio volumio[997]: info: ------------------------------------------- Dec 26 15:39:37 volumio volumio[997]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:37 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:37 volumio volumio[997]: info: Shairport-Sync Started Dec 26 15:39:37 volumio volumio[997]: Error adding Membership: Error: addMembership EINVAL Dec 26 15:39:37 volumio volumio[997]: info: Shairport-Sync Started Dec 26 15:39:37 volumio volumio[997]: info: Shairport-Sync Started Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:37 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:37 volumio volumio[997]: info: touch_display: X display number found: Dec 26 15:39:37 volumio volumio[997]: info: touch_display: X display number found: 0 Dec 26 15:39:37 volumio startx[1255]: X.Org X Server 1.20.4 Dec 26 15:39:37 volumio startx[1255]: X Protocol Version 11, Revision 0 Dec 26 15:39:37 volumio startx[1255]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Dec 26 15:39:37 volumio startx[1255]: Current Operating System: Linux volumio 6.6.62-v7l+ #1816 SMP Mon Nov 18 15:33:33 GMT 2024 armv7l Dec 26 15:39:37 volumio startx[1255]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=D8:3A:DD:32:59:03 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=7f0c0e47-027d-47ad-bd0c-5159b014252e imgfile=/volumio_current.sqsh bootpart=UUID=10D8-1DF5 datapart=UUID=307f8728-204c-4df1-9dcc-f9fb9dec6fbe uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no cfg80211.ieee80211_regdom=HU Dec 26 15:39:37 volumio startx[1255]: Build Date: 04 April 2023 07:50:56AM Dec 26 15:39:37 volumio startx[1255]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Dec 26 15:39:37 volumio startx[1255]: Current version of pixman: 0.36.0 Dec 26 15:39:37 volumio startx[1255]: Before reporting problems, check http://wiki.x.org Dec 26 15:39:37 volumio startx[1255]: to make sure that you have the latest version. Dec 26 15:39:37 volumio startx[1255]: Markers: (--) probed, (**) from config file, (==) default setting, Dec 26 15:39:37 volumio startx[1255]: (++) from command line, (!!) notice, (II) informational, Dec 26 15:39:37 volumio startx[1255]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Dec 26 15:39:37 volumio startx[1255]: (==) Log file: "/var/log/Xorg.0.log", Time: Fri Dec 26 15:39:37 2025 Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:39:37 volumio volumio[997]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Dec 26 15:39:37 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:37 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:37 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:37 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:37 volumio startx[1255]: (==) Using config directory: "/etc/X11/xorg.conf.d" Dec 26 15:39:37 volumio startx[1255]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Dec 26 15:39:37 volumio volumio[997]: info: touch_display: X display number found: 0 Dec 26 15:39:37 volumio go-librespot[1256]: time="2025-12-26T15:39:37+01:00" level=info msg="running go-librespot 0.4.0" Dec 26 15:39:37 volumio go-librespot[1256]: time="2025-12-26T15:39:37+01:00" level=debug msg="app state loaded" Dec 26 15:39:37 volumio go-librespot[1256]: time="2025-12-26T15:39:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::volumioPlay Dec 26 15:39:38 volumio volumio[997]: info: CoreStateMachine::play index undefined Dec 26 15:39:38 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:38 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:38 volumio volumio[997]: info: CoreStateMachine::startPlaybackTimer Dec 26 15:39:38 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:38 volumio volumio[997]: info: [1766759978125] ControllerSpotify::clearAddPlayTrack Dec 26 15:39:38 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/play Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=info msg="zeroconf server listening on port 39669" Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:39:38 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:38 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:38 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="obtained new client token: AAA1ZUket8Ew5DrdfzeYgi79GYSv8s77EOqUmFScLzVjMmP+PdEvcFKZ9a9lKTUmkm49jw2SRZwOD3bE0INYNCduWvl8nfD6yPJMQUqRmHshjV56S00z2PxsaetGZOvfCsoQLr2Y04DP8BElvHH+KRaY9XQoym3q+tBmZUsTTOQ/rWyDw2hLHtbEJzDpJyVGBYEYcYARSsGZttWtTFA3R7z1Fp0IUwrH6PM1oNjX0UaCWkX25KIFKFfpoQ==" Dec 26 15:39:38 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 26 15:39:38 volumio volumio[997]: info: touch_display: Setting screensaver timeout to 25 seconds. Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="completed keyexchange" Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=debug msg="completed challenge" Dec 26 15:39:38 volumio go-librespot[1256]: time="2025-12-26T15:39:38+01:00" level=info msg="authenticated AP" username="xo*********************89" Dec 26 15:39:38 volumio systemd[1]: systemd-fsckd.service: Succeeded. Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=info msg="authenticated Login5" username="xo*********************89" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="initializing zeroconf session" username="xo*********************89" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="dealer connection opened" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=trace msg="starting accesspoint recv loop" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=trace msg="starting dealer recv loop" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=trace msg="received accesspoint ping" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="resolved context of track" uri="spotify:track:7ACxUo21jtTHzy7ZEV56vU" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7ACxUo21jtTHzy7ZEV56vU" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7ACxUo21jtTHzy7ZEV56vU" Dec 26 15:39:39 volumio go-librespot[1256]: time="2025-12-26T15:39:39+01:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Dec 26 15:39:39 volumio sh[547]: timed out Dec 26 15:39:39 volumio dhcpcd[585]: timed out Dec 26 15:39:39 volumio sh[547]: dhcpcd exited Dec 26 15:39:39 volumio dhcpcd[585]: dhcpcd exited Dec 26 15:39:39 volumio sh[547]: ifup: failed to bring up eth0 Dec 26 15:39:39 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Dec 26 15:39:39 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Dec 26 15:39:40 volumio volumio[997]: info: go-librespot daemon successfully initialized Dec 26 15:39:40 volumio go-librespot[1256]: time="2025-12-26T15:39:40+01:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Dec 26 15:39:41 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Dec 26 15:39:41 volumio sudo[1403]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 15:39:41 volumio sudo[1403]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:41 volumio volumio[997]: info: CoreCommandRouter::volumioNext Dec 26 15:39:41 volumio volumio[997]: info: CoreStateMachine::next Dec 26 15:39:41 volumio volumio[997]: info: CoreStateMachine::stop Dec 26 15:39:41 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:41 volumio volumio[997]: info: CoreStateMachine::play index undefined Dec 26 15:39:41 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:41 volumio volumio[997]: info: CorePlayQueue::getTrack 1 Dec 26 15:39:41 volumio sudo[1403]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:41 volumio sudo[1405]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 15:39:41 volumio sudo[1405]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:41 volumio sudo[1405]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:41 volumio sudo[1409]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 15:39:41 volumio sudo[1409]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:41 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Dec 26 15:39:41 volumio sudo[1409]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:41 volumio volumio[997]: info: Upmpdcli Daemon Started Dec 26 15:39:41 volumio volumio[1414]: Generating RSA private key, 4096 bit long modulus (2 primes) Dec 26 15:39:41 volumio volumio[997]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 15:39:41 volumio go-librespot[1256]: time="2025-12-26T15:39:41+01:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Dec 26 15:39:41 volumio go-librespot[1256]: time="2025-12-26T15:39:41+01:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" Dec 26 15:39:41 volumio go-librespot[1256]: time="2025-12-26T15:39:41+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:39:41 volumio go-librespot[1256]: time="2025-12-26T15:39:41+01:00" level=debug msg="selected format OGG_VORBIS_320 (49bac4a26b151a0f3a10a92572d72506fecd80af)" uri="spotify:track:7ACxUo21jtTHzy7ZEV56vU" Dec 26 15:39:41 volumio go-librespot[1256]: time="2025-12-26T15:39:41+01:00" level=debug msg="requested aes key for file 49bac4a26b151a0f3a10a92572d72506fecd80af, gid: 7ACxUo21jtTHzy7ZEV56vU" Dec 26 15:39:42 volumio volumio[1414]: ............++++ Dec 26 15:39:43 volumio volumio[997]: info: Initializing connection to go-librespot Websocket Dec 26 15:39:43 volumio go-librespot[1256]: time="2025-12-26T15:39:43+01:00" level=debug msg="new websocket client" Dec 26 15:39:43 volumio volumio[997]: info: Connection to go-librespot Websocket established Dec 26 15:39:44 volumio volumio[997]: info: CoreCommandRouter::volumioGetQueue Dec 26 15:39:44 volumio volumio[997]: info: CoreStateMachine::getQueue Dec 26 15:39:44 volumio volumio[997]: info: CorePlayQueue::getQueue Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 15:39:45 volumio volumio[997]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 15:39:46 volumio volumio[997]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 15:39:46 volumio volumio[997]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 15:39:46 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:46 volumio volumio[997]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 15:39:46 volumio volumio[997]: info: MyVolumio login type: Token Dec 26 15:39:46 volumio volumio[997]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 15:39:46 volumio volumio[997]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 15:39:47 volumio volumio[997]: info: Starting Streaming Service Transparent Proxy Dec 26 15:39:47 volumio volumio[997]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 15:39:47 volumio volumio[997]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 15:39:47 volumio volumio[997]: info: Streaming services startup Dec 26 15:39:47 volumio volumio[997]: info: Starting Streaming Daemon Dec 26 15:39:47 volumio sudo[1533]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 15:39:47 volumio sudo[1533]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:47 volumio volumio[997]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 15:39:47 volumio sudo[1533]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:47 volumio volumio[997]: info: Getting Spotify volume Dec 26 15:39:47 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 26 15:39:47 volumio volumio[997]: info: Preload queue cleared Dec 26 15:39:47 volumio volumio[997]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 26 15:39:47 volumio volumio[997]: info: CoreStateMachine::ClearQueue Dec 26 15:39:47 volumio volumio[997]: info: CoreStateMachine::stop Dec 26 15:39:47 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:47 volumio volumio[997]: info: CorePlayQueue::clearPlayQueue Dec 26 15:39:47 volumio volumio[997]: info: CorePlayQueue::saveQueue Dec 26 15:39:47 volumio volumio[997]: info: CoreCommandRouter::volumioPushQueue Dec 26 15:39:47 volumio volumio[997]: info: CoreStateMachine::addQueueItems Dec 26 15:39:47 volumio volumio[997]: info: CorePlayQueue::addQueueItems Dec 26 15:39:47 volumio volumio[997]: info: Preload queue cleared Dec 26 15:39:47 volumio volumio[997]: info: Adding Item to queue: spotify:track:7ACxUo21jtTHzy7ZEV56vU Dec 26 15:39:47 volumio volumio[997]: info: Exploding uri spotify:track:7ACxUo21jtTHzy7ZEV56vU in service spop Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:7ACxUo21jtTHzy7ZEV56vU Dec 26 15:39:47 volumio volumio[997]: info: Adding Item to queue: spotify:track:3Jnxngdff0lVu2rza1GVx6 Dec 26 15:39:47 volumio volumio[997]: info: Exploding uri spotify:track:3Jnxngdff0lVu2rza1GVx6 in service spop Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:3Jnxngdff0lVu2rza1GVx6 Dec 26 15:39:47 volumio volumio[997]: info: Adding Item to queue: spotify:track:2wNEcJHnFxoKZIrxjxF5jL Dec 26 15:39:47 volumio volumio[997]: info: Exploding uri spotify:track:2wNEcJHnFxoKZIrxjxF5jL in service spop Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:2wNEcJHnFxoKZIrxjxF5jL Dec 26 15:39:47 volumio volumio[997]: info: Adding Item to queue: spotify:track:2E7W1X4maFFcjHrVrFA7Vs Dec 26 15:39:47 volumio volumio[997]: info: Exploding uri spotify:track:2E7W1X4maFFcjHrVrFA7Vs in service spop Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:2E7W1X4maFFcjHrVrFA7Vs Dec 26 15:39:47 volumio volumio[997]: info: Adding Item to queue: spotify:track:14M0JWFCnsKNGSvzDn0j6q Dec 26 15:39:47 volumio volumio[997]: info: Exploding uri spotify:track:14M0JWFCnsKNGSvzDn0j6q in service spop Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:14M0JWFCnsKNGSvzDn0j6q Dec 26 15:39:47 volumio volumio[997]: error: Cannot start Volumio Streaming Daemon Dec 26 15:39:47 volumio volumio[997]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 26 15:39:47 volumio volumio[997]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 26 15:39:47 volumio volumio[997]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 26 15:39:47 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:47 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: SPOTIFY VOLUME undefined Dec 26 15:39:47 volumio volumio[997]: SPOTIFY: VOLUMIO VOLUME 44 Dec 26 15:39:47 volumio volumio[997]: info: Aligning Spotify Volume to Volumio Volume Dec 26 15:39:47 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:47 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:47 volumio volumio[997]: info: Setting Spotify Volume from Volumio: 44 Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7ACxUo21jtTHzy7ZEV56vU","service":"spop","name":"Crazy Train","artist":"Ozzy Osbourne","album":"Blizzard Of Ozz (40th Anniversary Expanded Edition)","type":"song","duration":293,"albumart":"https://i.scdn.co/image/ab67616d0000b2734936b5b7caeb7524e50fd8cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:48 volumio volumio[1414]: ........................................................++++ Dec 26 15:39:48 volumio volumio[1414]: e is 65537 (0x010001) Dec 26 15:39:48 volumio volumio[1414]: writing RSA key Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2E7W1X4maFFcjHrVrFA7Vs","service":"spop","name":"Bark at the Moon","artist":"Ozzy Osbourne","album":"Bark At The Moon (Expanded Edition)","type":"song","duration":257,"albumart":"https://i.scdn.co/image/ab67616d0000b273feeaf9a5c2beb414fb2b7090","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Jnxngdff0lVu2rza1GVx6","service":"spop","name":"Paranoid - 2009 Remaster","artist":"Black Sabbath","album":"Paranoid","type":"song","duration":167,"albumart":"https://i.scdn.co/image/ab67616d0000b273605b25c031f809d78054a13c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2wNEcJHnFxoKZIrxjxF5jL","service":"spop","name":"Changes - 2009 Remaster","artist":"Black Sabbath","album":"Vol. 4","type":"song","duration":284,"albumart":"https://i.scdn.co/image/ab67616d0000b2730a774ec695cc0a967250b966","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:48 volumio volumio[997]: STREAMING PROXY: Starting server on port 3245 Dec 26 15:39:48 volumio volumio[997]: Node JS runtime: 14 Dec 26 15:39:48 volumio volumio[997]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","service":"spop","name":"War Pigs - Charity Version","artist":"Judas Priest","album":"War Pigs (Charity Version)","type":"song","duration":484,"albumart":"https://i.scdn.co/image/ab67616d0000b2730aa8fb052090c291d251785d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:48 volumio volumio[997]: info: CoreCommandRouter::volumioPushQueue Dec 26 15:39:48 volumio volumio[997]: info: CorePlayQueue::saveQueue Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::updateTrackBlock Dec 26 15:39:48 volumio volumio[997]: info: CorePlayQueue::getTrackBlock Dec 26 15:39:48 volumio volumio[997]: info: CoreCommandRouter::volumioPlay Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::play index 4 Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::addQueueItems Dec 26 15:39:48 volumio volumio[997]: info: CorePlayQueue::addQueueItems Dec 26 15:39:48 volumio volumio[997]: info: Preload queue cleared Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:755bvJDSA3LNcNuFgBT9LK Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:755bvJDSA3LNcNuFgBT9LK in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:755bvJDSA3LNcNuFgBT9LK Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0S3gpZzlT9Hb7CCSV2owX7 Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0S3gpZzlT9Hb7CCSV2owX7 in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0S3gpZzlT9Hb7CCSV2owX7 Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:6KmJMlyPp0rPR7LloToCaF Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:6KmJMlyPp0rPR7LloToCaF in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:6KmJMlyPp0rPR7LloToCaF Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:29KYPEsbcMcVKnd6iyu6Q5 Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:29KYPEsbcMcVKnd6iyu6Q5 in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:29KYPEsbcMcVKnd6iyu6Q5 Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:7w6PJe5KBPyvuRYxFkPssC Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:7w6PJe5KBPyvuRYxFkPssC in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:7w6PJe5KBPyvuRYxFkPssC Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:02VKxjok07ypt3oFlGRjmH Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:02VKxjok07ypt3oFlGRjmH in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:02VKxjok07ypt3oFlGRjmH Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:3XclwoQxz4p6Dl7VUf90KW Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:3XclwoQxz4p6Dl7VUf90KW in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:3XclwoQxz4p6Dl7VUf90KW Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:2ov8L95QD25TLpZAZPYWXL Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:2ov8L95QD25TLpZAZPYWXL in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:2ov8L95QD25TLpZAZPYWXL Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0ElAcOj8tudMA6X6KZ7SMO Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0ElAcOj8tudMA6X6KZ7SMO in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0ElAcOj8tudMA6X6KZ7SMO Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:5axOkQnmQmwtjr4bv1Xt7i Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:5axOkQnmQmwtjr4bv1Xt7i in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:5axOkQnmQmwtjr4bv1Xt7i Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:4zgHtuasZkiZu1caZwxF5P Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:4zgHtuasZkiZu1caZwxF5P in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:4zgHtuasZkiZu1caZwxF5P Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:2lxq02Zit1kI8S0THAYkAZ Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:2lxq02Zit1kI8S0THAYkAZ in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:2lxq02Zit1kI8S0THAYkAZ Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:31dqpLUModJWNbxrXu6TWd Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:31dqpLUModJWNbxrXu6TWd in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:31dqpLUModJWNbxrXu6TWd Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:7CZyCXKG6d5ALeq41sLzbw Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:7CZyCXKG6d5ALeq41sLzbw in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:7CZyCXKG6d5ALeq41sLzbw Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:78PKCefXwDLbl4FVO1Pjzh Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:78PKCefXwDLbl4FVO1Pjzh in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:78PKCefXwDLbl4FVO1Pjzh Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:3inSAmtjMjAePyBUqh5Z3r Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:3inSAmtjMjAePyBUqh5Z3r in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:3inSAmtjMjAePyBUqh5Z3r Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:4nvYDy427VvA1TcEkdgZII Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:4nvYDy427VvA1TcEkdgZII in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:4nvYDy427VvA1TcEkdgZII Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:43thLwzSasUUZEYjYPeJh3 Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:43thLwzSasUUZEYjYPeJh3 in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:43thLwzSasUUZEYjYPeJh3 Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:7vGOHxPXPDEc3YOyihLuPt Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:7vGOHxPXPDEc3YOyihLuPt in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:7vGOHxPXPDEc3YOyihLuPt Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:1bJ5FuncHc6wyDHBvJ0xF6 Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:1bJ5FuncHc6wyDHBvJ0xF6 in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:1bJ5FuncHc6wyDHBvJ0xF6 Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:1Hs2MG2LBJaSPk7X0fzmfk Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:1Hs2MG2LBJaSPk7X0fzmfk in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:1Hs2MG2LBJaSPk7X0fzmfk Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:6VfoT86lDJ18YhLCDHKgEL Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:6VfoT86lDJ18YhLCDHKgEL in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:6VfoT86lDJ18YhLCDHKgEL Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:1qdXodVqWyuzRKMDzAz1Xe Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:1qdXodVqWyuzRKMDzAz1Xe in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:1qdXodVqWyuzRKMDzAz1Xe Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:3IKJNHnVZ2bXGjAFBJiUYo Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:3IKJNHnVZ2bXGjAFBJiUYo in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:3IKJNHnVZ2bXGjAFBJiUYo Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:09EQqFGUTJW6X4NksMPM0O Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:09EQqFGUTJW6X4NksMPM0O in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:09EQqFGUTJW6X4NksMPM0O Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:37gJgdjcyAIeeAeWzEIawU Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:37gJgdjcyAIeeAeWzEIawU in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:37gJgdjcyAIeeAeWzEIawU Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0VfXQxbM0doaDw2fMI8Ima Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0VfXQxbM0doaDw2fMI8Ima in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0VfXQxbM0doaDw2fMI8Ima Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:046x8yuXjJFPaaQI6Iyz9e Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:046x8yuXjJFPaaQI6Iyz9e in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:046x8yuXjJFPaaQI6Iyz9e Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:42HN6p1xRxAn439UH1MJ6G Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:42HN6p1xRxAn439UH1MJ6G in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:42HN6p1xRxAn439UH1MJ6G Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0p9dEwFFw14hWTvS9v5NLU Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0p9dEwFFw14hWTvS9v5NLU in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0p9dEwFFw14hWTvS9v5NLU Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0aqHkYkm55l9mI8xKoe8Lg Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0aqHkYkm55l9mI8xKoe8Lg in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0aqHkYkm55l9mI8xKoe8Lg Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:6kAOsnRUgp21bPiUoVZeuJ Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:6kAOsnRUgp21bPiUoVZeuJ in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:6kAOsnRUgp21bPiUoVZeuJ Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:4MN0ZmFppiiQsPE9HQKKsH Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:4MN0ZmFppiiQsPE9HQKKsH in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:4MN0ZmFppiiQsPE9HQKKsH Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:0i1RTnH2Lj5gTDRU5wtyT2 Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:0i1RTnH2Lj5gTDRU5wtyT2 in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:0i1RTnH2Lj5gTDRU5wtyT2 Dec 26 15:39:48 volumio volumio[997]: info: Adding Item to queue: spotify:track:1BTpL8k7DytUPa2sNYs53P Dec 26 15:39:48 volumio volumio[997]: info: Exploding uri spotify:track:1BTpL8k7DytUPa2sNYs53P in service spop Dec 26 15:39:48 volumio volumio[997]: SPOTIFY: EXPLODING URI:spotify:track:1BTpL8k7DytUPa2sNYs53P Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::stop Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::play index undefined Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:48 volumio volumio[997]: info: CorePlayQueue::getTrack 4 Dec 26 15:39:48 volumio volumio[997]: info: CoreStateMachine::startPlaybackTimer Dec 26 15:39:48 volumio volumio[997]: info: CorePlayQueue::getTrack 4 Dec 26 15:39:48 volumio volumio[997]: info: [1766759988765] ControllerSpotify::clearAddPlayTrack Dec 26 15:39:48 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/play Dec 26 15:39:48 volumio volumio[997]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 26 15:39:49 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: SETTING SPOTIFY VOLUME 44 Dec 26 15:39:49 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/volume Dec 26 15:39:49 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4zgHtuasZkiZu1caZwxF5P","service":"spop","name":"Planet Caravan - 2009 Remaster","artist":"Black Sabbath","album":"Paranoid","type":"song","duration":269,"albumart":"https://i.scdn.co/image/ab67616d0000b273605b25c031f809d78054a13c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7w6PJe5KBPyvuRYxFkPssC","service":"spop","name":"No More Tears","artist":"Ozzy Osbourne","album":"No More Tears (Expanded Edition)","type":"song","duration":444,"albumart":"https://i.scdn.co/image/ab67616d0000b273509342e69eb341df70e5c2e3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0ElAcOj8tudMA6X6KZ7SMO","service":"spop","name":"Children of the Grave - 2009 Remaster","artist":"Black Sabbath","album":"Master of Reality","type":"song","duration":315,"albumart":"https://i.scdn.co/image/ab67616d0000b27395326acf47fb8dd45e61c8d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:31dqpLUModJWNbxrXu6TWd","service":"spop","name":"Shot in the Dark","artist":"Ozzy Osbourne","album":"The Ultimate Sin","type":"song","duration":256,"albumart":"https://i.scdn.co/image/ab67616d0000b273ca110425c6233c263beb0a4f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2lxq02Zit1kI8S0THAYkAZ","service":"spop","name":"I Don't Know","artist":"Ozzy Osbourne","album":"Blizzard Of Ozz (40th Anniversary Expanded Edition)","type":"song","duration":315,"albumart":"https://i.scdn.co/image/ab67616d0000b2734936b5b7caeb7524e50fd8cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7CZyCXKG6d5ALeq41sLzbw","service":"spop","name":"Take What You Want (feat. Ozzy Osbourne & Travis Scott)","artist":"Post Malone","album":"Hollywood's Bleeding","type":"song","duration":229,"albumart":"https://i.scdn.co/image/ab67616d0000b2739478c87599550dd73bfa7e02","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:78PKCefXwDLbl4FVO1Pjzh","service":"spop","name":"Dreamer","artist":"Ozzy Osbourne","album":"Down To Earth","type":"song","duration":284,"albumart":"https://i.scdn.co/image/ab67616d0000b2736ab3121cb80e3d8da28f5b77","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4nvYDy427VvA1TcEkdgZII","service":"spop","name":"Hellraiser","artist":"Ozzy Osbourne","album":"No More Tears (Expanded Edition)","type":"song","duration":292,"albumart":"https://i.scdn.co/image/ab67616d0000b273509342e69eb341df70e5c2e3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1bJ5FuncHc6wyDHBvJ0xF6","service":"spop","name":"Sweet Leaf - 2009 Remaster","artist":"Black Sabbath","album":"Master of Reality","type":"song","duration":302,"albumart":"https://i.scdn.co/image/ab67616d0000b27395326acf47fb8dd45e61c8d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:43thLwzSasUUZEYjYPeJh3","service":"spop","name":"Close My Eyes Forever","artist":"Lita Ford","album":"Lita","type":"song","duration":283,"albumart":"https://i.scdn.co/image/ab67616d0000b2732dbf0cc843a4a0fe8c8f5482","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3inSAmtjMjAePyBUqh5Z3r","service":"spop","name":"Changes","artist":"Kelly Osbourne","album":"Changes","type":"song","duration":247,"albumart":"https://i.scdn.co/image/ab67616d0000b2737db6afc41fbeb23f8b529254","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0S3gpZzlT9Hb7CCSV2owX7","service":"spop","name":"Mama, I'm Coming Home","artist":"Ozzy Osbourne","album":"No More Tears (Expanded Edition)","type":"song","duration":251,"albumart":"https://i.scdn.co/image/ab67616d0000b273509342e69eb341df70e5c2e3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7vGOHxPXPDEc3YOyihLuPt","service":"spop","name":"Suicide Solution","artist":"Ozzy Osbourne","album":"Blizzard Of Ozz (40th Anniversary Expanded Edition)","type":"song","duration":258,"albumart":"https://i.scdn.co/image/ab67616d0000b2734936b5b7caeb7524e50fd8cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3IKJNHnVZ2bXGjAFBJiUYo","service":"spop","name":"God Is Dead?","artist":"Black Sabbath","album":"13","type":"song","duration":532,"albumart":"https://i.scdn.co/image/ab67616d0000b273a7e7bfdfd15d41435f17ba64","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1qdXodVqWyuzRKMDzAz1Xe","service":"spop","name":"Sabbra Cadabra (2009 Remaster)","artist":"Black Sabbath","album":"Sabbath Bloody Sabbath","type":"song","duration":355,"albumart":"https://i.scdn.co/image/ab67616d0000b273e3eaed3e5895ca02d5b6a868","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:49 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1Hs2MG2LBJaSPk7X0fzmfk","service":"spop","name":"See You on the Other Side","artist":"Ozzy Osbourne","album":"Ozzmosis (Expanded Edition)","type":"song","duration":370,"albumart":"https://i.scdn.co/image/ab67616d0000b27320904d686b3d8d433834e079","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:09EQqFGUTJW6X4NksMPM0O","service":"spop","name":"Into the Void - 2009 Remaster","artist":"Black Sabbath","album":"Master of Reality","type":"song","duration":371,"albumart":"https://i.scdn.co/image/ab67616d0000b27395326acf47fb8dd45e61c8d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6VfoT86lDJ18YhLCDHKgEL","service":"spop","name":"Solitude - 2009 Remaster","artist":"Black Sabbath","album":"Master of Reality","type":"song","duration":301,"albumart":"https://i.scdn.co/image/ab67616d0000b27395326acf47fb8dd45e61c8d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:37gJgdjcyAIeeAeWzEIawU","service":"spop","name":"Electric Funeral - 2009 Remaster","artist":"Black Sabbath","album":"Paranoid","type":"song","duration":289,"albumart":"https://i.scdn.co/image/ab67616d0000b273605b25c031f809d78054a13c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5axOkQnmQmwtjr4bv1Xt7i","service":"spop","name":"I Don't Wanna Stop","artist":"Ozzy Osbourne","album":"Black Rain (Expanded Edition)","type":"song","duration":239,"albumart":"https://i.scdn.co/image/ab67616d0000b273c48ac94a47b4948070b49f29","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6KmJMlyPp0rPR7LloToCaF","service":"spop","name":"Black Sabbath - 2009 Remaster","artist":"Black Sabbath","album":"Black Sabbath","type":"song","duration":380,"albumart":"https://i.scdn.co/image/ab67616d0000b273e61731abae915074b93416e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1BTpL8k7DytUPa2sNYs53P","service":"spop","name":"Iron Head","artist":"Rob Zombie","album":"The Sinister Urge","type":"song","duration":251,"albumart":"https://i.scdn.co/image/ab67616d0000b2731d624949c965172774b98178","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:02VKxjok07ypt3oFlGRjmH","service":"spop","name":"The Wizard - 2009 Remaster","artist":"Black Sabbath","album":"Black Sabbath","type":"song","duration":262,"albumart":"https://i.scdn.co/image/ab67616d0000b273e61731abae915074b93416e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:42HN6p1xRxAn439UH1MJ6G","service":"spop","name":"Orchid - 2009 Remaster","artist":"Black Sabbath","album":"Master of Reality","type":"song","duration":91,"albumart":"https://i.scdn.co/image/ab67616d0000b27395326acf47fb8dd45e61c8d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0aqHkYkm55l9mI8xKoe8Lg","service":"spop","name":"Supernaut - 2020 Remaster","artist":"Black Sabbath","album":"Vol. 4 (2021 Remaster)","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab67616d0000b2733d511b2f89420cbe574773a3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:046x8yuXjJFPaaQI6Iyz9e","service":"spop","name":"Evil Woman, Don't Play Your Games with Me - 2009 Remaster","artist":"Black Sabbath","album":"Black Sabbath","type":"song","duration":200,"albumart":"https://i.scdn.co/image/ab67616d0000b273e61731abae915074b93416e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioGetVisibleSources Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrack 4 Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 26 15:39:50 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:50 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrack 4 Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrack 4 Dec 26 15:39:50 volumio volumio[997]: info: Listing playlists Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0p9dEwFFw14hWTvS9v5NLU","service":"spop","name":"Fairies Wear Boots - 2009 Remaster","artist":"Black Sabbath","album":"Paranoid","type":"song","duration":373,"albumart":"https://i.scdn.co/image/ab67616d0000b273605b25c031f809d78054a13c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0i1RTnH2Lj5gTDRU5wtyT2","service":"spop","name":"Over the Mountain","artist":"Ozzy Osbourne","album":"Diary Of A Madman","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab67616d0000b273074a1951cb329bb8afb63142","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6kAOsnRUgp21bPiUoVZeuJ","service":"spop","name":"Patient Number 9 (feat. Jeff Beck)","artist":"Ozzy Osbourne","album":"Patient Number 9 (feat. Jeff Beck)","type":"song","duration":441,"albumart":"https://i.scdn.co/image/ab67616d0000b2732a646e80fead1a438b116b31","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3XclwoQxz4p6Dl7VUf90KW","service":"spop","name":"N.I.B. - 2009 Remaster","artist":"Black Sabbath","album":"Black Sabbath","type":"song","duration":366,"albumart":"https://i.scdn.co/image/ab67616d0000b273e61731abae915074b93416e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0VfXQxbM0doaDw2fMI8Ima","service":"spop","name":"Snowblind - 2009 Remaster","artist":"Black Sabbath","album":"Vol. 4","type":"song","duration":328,"albumart":"https://i.scdn.co/image/ab67616d0000b2730a774ec695cc0a967250b966","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:755bvJDSA3LNcNuFgBT9LK","service":"spop","name":"Iron Man - 2009 Remaster","artist":"Black Sabbath","album":"Paranoid","type":"song","duration":354,"albumart":"https://i.scdn.co/image/ab67616d0000b273605b25c031f809d78054a13c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4MN0ZmFppiiQsPE9HQKKsH","service":"spop","name":"Gets Me Through","artist":"Ozzy Osbourne","album":"Down To Earth","type":"song","duration":304,"albumart":"https://i.scdn.co/image/ab67616d0000b2736ab3121cb80e3d8da28f5b77","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2ov8L95QD25TLpZAZPYWXL","service":"spop","name":"Mr. Crowley","artist":"Ozzy Osbourne","album":"Blizzard Of Ozz (40th Anniversary Expanded Edition)","type":"song","duration":302,"albumart":"https://i.scdn.co/image/ab67616d0000b2734936b5b7caeb7524e50fd8cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:50 volumio volumio[997]: info: Preload queue cleared Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::ClearQueue Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::stop Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::clearPlayQueue Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::saveQueue Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioPushQueue Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::addQueueItems Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::addQueueItems Dec 26 15:39:50 volumio volumio[997]: info: Preload queue cleared Dec 26 15:39:50 volumio volumio[997]: info: Adding Item to queue: spotify:track:14M0JWFCnsKNGSvzDn0j6q Dec 26 15:39:50 volumio volumio[997]: info: Using cached record of: spotify:track:14M0JWFCnsKNGSvzDn0j6q Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioPushQueue Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::saveQueue Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::updateTrackBlock Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrackBlock Dec 26 15:39:50 volumio volumio[997]: info: CoreCommandRouter::volumioPlay Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::play index 0 Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::stop Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::play index undefined Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:50 volumio volumio[997]: info: CoreStateMachine::startPlaybackTimer Dec 26 15:39:50 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:50 volumio volumio[997]: info: [1766759990901] ControllerSpotify::clearAddPlayTrack Dec 26 15:39:50 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/play Dec 26 15:39:51 volumio volumio[997]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:29KYPEsbcMcVKnd6iyu6Q5","service":"spop","name":"Sabbath Bloody Sabbath (2009 Remaster)","artist":"Black Sabbath","album":"Sabbath Bloody Sabbath","type":"song","duration":344,"albumart":"https://i.scdn.co/image/ab67616d0000b273e3eaed3e5895ca02d5b6a868","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 26 15:39:51 volumio volumio[997]: info: CoreCommandRouter::volumioPushQueue Dec 26 15:39:51 volumio volumio[997]: info: CorePlayQueue::saveQueue Dec 26 15:39:51 volumio volumio[997]: info: CoreStateMachine::updateTrackBlock Dec 26 15:39:51 volumio volumio[997]: info: CorePlayQueue::getTrackBlock Dec 26 15:39:52 volumio volumio[997]: info: MyVolumio token set successfully Dec 26 15:39:52 volumio volumio[997]: info: MYVOLUMIO: Adding device Dec 26 15:39:52 volumio volumio[997]: info: MYVOLUMIO: Evaluating Server Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:39:52 volumio volumio[997]: info: MyVolumio status changed Dec 26 15:39:52 volumio volumio[997]: info: Streaming services startup Dec 26 15:39:52 volumio volumio[997]: info: Starting Streaming Daemon Dec 26 15:39:52 volumio volumio[997]: info: Removing browser output: myVolumio user plan is not superstar Dec 26 15:39:52 volumio volumio[997]: info: Removing audio output: Dec 26 15:39:52 volumio volumio[997]: info: Stoppping Tunnel 1 Dec 26 15:39:52 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:52 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:52 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 26 15:39:52 volumio sudo[1592]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 15:39:52 volumio sudo[1592]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:52 volumio sudo[1594]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 26 15:39:52 volumio sudo[1594]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:39:52 volumio sudo[1592]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:52 volumio volumio[997]: error: Cannot start Volumio Streaming Daemon Dec 26 15:39:52 volumio volumio[997]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 26 15:39:52 volumio volumio[997]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 26 15:39:52 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 26 15:39:52 volumio sudo[1594]: pam_unix(sudo:session): session closed for user root Dec 26 15:39:52 volumio volumio[997]: info: Remote SSH Stopped Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 15:39:53 volumio volumio[997]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 26 15:39:53 volumio volumio[997]: info: Received Get System Version Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:39:53 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:53 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:53 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:53 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:54 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:39:54 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:54 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:54 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:54 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:54 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:54 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:54 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:56 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:39:56 volumio volumio[997]: info: Received Get System Info Dec 26 15:39:56 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:39:56 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:39:56 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:39:56 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:39:56 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:39:56 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:39:56 volumio go-librespot[1256]: time="2025-12-26T15:39:56+01:00" level=debug msg="received connection id: NGI3YTkzODItOTY1...NEMzRDQ3MjU5Nw==" Dec 26 15:39:56 volumio go-librespot[1256]: time="2025-12-26T15:39:56+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7ACxUo21jtTHzy7ZEV56vU: failed retrieving audio key: context deadline exceeded" Dec 26 15:39:56 volumio volumio[997]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 15:39:56 volumio volumio[997]: info: Spotify volume: 100 Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="resolved context of track" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:39:57 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","play_origin":"go-librespot"}} Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="selected format OGG_VORBIS_320 (61fbd44a5379011a2768354f2a45c527b0103e8a)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:39:57 volumio go-librespot[1256]: time="2025-12-26T15:39:57+01:00" level=debug msg="requested aes key for file 61fbd44a5379011a2768354f2a45c527b0103e8a, gid: 14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:39:57 volumio volumio[997]: info: Setting Geolocation for MyVolumio to eu7 Dec 26 15:39:57 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:57 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:57 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:58 volumio volumio[997]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 26 15:39:58 volumio volumio[997]: info: Updating MyVolumio device info Dec 26 15:39:58 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:39:59 volumio volumio[997]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 26 15:39:59 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 26 15:40:01 volumio systemd[1]: systemd-timedated.service: Succeeded. Dec 26 15:40:01 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 15:40:01 volumio volumio[997]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 26 15:40:01 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:40:01 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:02 volumio volumio[997]: info: MYVOLUMIO: Adding device Dec 26 15:40:02 volumio volumio[997]: info: MYVOLUMIO: Evaluating Server Dec 26 15:40:03 volumio volumio[997]: info: Setting Geolocation for MyVolumio to eu7 Dec 26 15:40:03 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:03 volumio volumio[997]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 26 15:40:04 volumio volumio[997]: info: Updating MyVolumio device info Dec 26 15:40:04 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:04 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:04 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:04 volumio volumio[997]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 26 15:40:05 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:40:05 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:05 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 15:40:06 volumio volumio-remote-updater[608]: No test mode Dec 26 15:40:06 volumio volumio-remote-updater[608]: No alpha test mode Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 26 15:40:06 volumio volumio[997]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

FIXES



    • Fix TIDAL low quality (AAC) playback
    • Fix for DLNA Server discovery
    • Fix for Plugins installation



NEW ADDITIONS



    • BLE-based onboarding setup

 

    • Update TIDAL SDK

 

","title":"Update v3.886","updateavailable":true} Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::volumioGetBrowseSources Dec 26 15:40:06 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:40:07 volumio volumio[997]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 26 15:40:07 volumio volumio[997]: info: Completed starting MyVolumio Plugin Dec 26 15:40:07 volumio volumio[997]: [Metrics] CommandRouter: 38s 242.14ms Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::volumiosetStartupVolume Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:07 volumio volumio[997]: info: VolumeController:: Setting startup Volume 30 Dec 26 15:40:07 volumio volumio[997]: info: VolumeController::SetAlsaVolume30 Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent Dec 26 15:40:07 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:07 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 15:40:07 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:07 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:07 volumio volumio[997]: SPOTIFY: SPOTIFY VOLUME 100 Dec 26 15:40:07 volumio volumio[997]: SPOTIFY: VOLUMIO VOLUME 30 Dec 26 15:40:07 volumio volumio[997]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 26 15:40:07 volumio volumio[997]: info: Setting Spotify Volume from Volumio: 30 Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 15:40:08 volumio volumio[997]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 26 15:40:08 volumio volumio[997]: info: Received Get System Version Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 15:40:08 volumio volumio[997]: info: Received Get System Info Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 15:40:08 volumio volumio[997]: info: Discovery: Getting this device information Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:40:08 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 26 15:40:08 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 26 15:40:09 volumio volumio[997]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Dec 26 15:40:09 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/volume Dec 26 15:40:09 volumio go-librespot[1256]: time="2025-12-26T15:40:09+01:00" level=trace msg="sent dealer ping" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:14M0JWFCnsKNGSvzDn0j6q: failed retrieving audio key: context deadline exceeded" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=trace msg="received dealer pong" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="update volume requested to 37347/65535" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="update volume requested to 28835/65535" Dec 26 15:40:12 volumio volumio[997]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="resolved context of track" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:40:12 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","play_origin":"go-librespot"}} Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="selected format OGG_VORBIS_320 (61fbd44a5379011a2768354f2a45c527b0103e8a)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:12 volumio go-librespot[1256]: time="2025-12-26T15:40:12+01:00" level=debug msg="requested aes key for file 61fbd44a5379011a2768354f2a45c527b0103e8a, gid: 14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:14 volumio volumio[997]: info: BOOT COMPLETED Dec 26 15:40:17 volumio ntpd[769]: Soliciting pool server 195.228.75.149 Dec 26 15:40:17 volumio ntpd[769]: Soliciting pool server 195.111.92.55 Dec 26 15:40:18 volumio ntpd[769]: Soliciting pool server 62.112.193.9 Dec 26 15:40:18 volumio ntpd[769]: Soliciting pool server 62.112.195.56 Dec 26 15:40:18 volumio ntpd[769]: Soliciting pool server 80.249.171.202 Dec 26 15:40:19 volumio ntpd[769]: Soliciting pool server 81.0.124.200 Dec 26 15:40:19 volumio ntpd[769]: Soliciting pool server 92.249.148.253 Dec 26 15:40:19 volumio ntpd[769]: Soliciting pool server 92.249.148.253 Dec 26 15:40:20 volumio ntpd[769]: Soliciting pool server 2001:ac8:26:62:0:1:0:21 Dec 26 15:40:20 volumio ntpd[769]: Soliciting pool server 62.112.195.26 Dec 26 15:40:20 volumio volumio[997]: info: CoreCommandRouter::volumioPlay Dec 26 15:40:20 volumio volumio[997]: info: CoreStateMachine::play index undefined Dec 26 15:40:20 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:40:20 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:20 volumio volumio[997]: info: CoreStateMachine::startPlaybackTimer Dec 26 15:40:20 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:20 volumio volumio[997]: info: [1766760020961] ControllerSpotify::clearAddPlayTrack Dec 26 15:40:20 volumio volumio[997]: info: Sending Spotify command with payload to local API: /player/play Dec 26 15:40:22 volumio ntpd[769]: Soliciting pool server 188.156.114.7 Dec 26 15:40:23 volumio ntpd[769]: Soliciting pool server 37.221.209.57 Dec 26 15:40:24 volumio ntpd[769]: Soliciting pool server 82.141.152.3 Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="update volume requested to 19660/65535" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:14M0JWFCnsKNGSvzDn0j6q: failed retrieving audio key: context deadline exceeded" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="handling skip_prev player command from a9b929e1ac1b683ef64cd12831744ceee35662e8" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="skip previous track" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=trace msg="received accesspoint pong ack" Dec 26 15:40:28 volumio volumio[997]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:40:28 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","play_origin":"go-librespot"}} Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="selected format OGG_VORBIS_320 (61fbd44a5379011a2768354f2a45c527b0103e8a)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=debug msg="requested aes key for file 61fbd44a5379011a2768354f2a45c527b0103e8a, gid: 14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:28 volumio go-librespot[1256]: time="2025-12-26T15:40:28+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::volumioGetState Dec 26 15:40:29 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="fetched first chunk of 38, total size is 19481719 bytes" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="created new output device" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=info msg="loaded track \"War Pigs - Charity Version\" (paused: false, position: 0ms, duration: 484779ms, prefetched: false)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="fetched chunk 2/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="scheduling prefetch in 455s" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="emitting websocket event: metadata" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="sending successful reply for dealer request" Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","name":"War Pigs - Charity Version","artist_names":["Judas Priest","Ozzy Osbourne"],"album_name":"War Pigs (Charity Version)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","position":0,"duration":484779,"release_date":"year:2025 month:9 day:26","track_number":1,"disc_number":1}} Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="fetched chunk 1/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="emitting websocket event: volume" Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="emitting websocket event: playing" Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","resume":false,"play_origin":"go-librespot"}} Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:29 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:29 volumio volumio[997]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:29 volumio volumio[997]: verbose: CURRENT POSITION 0 Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::syncState stateService play Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::syncState currentStatus stop Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="fetched chunk 3/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="resolved context of track" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","play_origin":"go-librespot"}} Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="selected format OGG_VORBIS_320 (61fbd44a5379011a2768354f2a45c527b0103e8a)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=debug msg="requested aes key for file 61fbd44a5379011a2768354f2a45c527b0103e8a, gid: 14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio go-librespot[1256]: time="2025-12-26T15:40:29+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:29 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:29 volumio volumio[997]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:29 volumio volumio[997]: verbose: CURRENT POSITION 0 Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::syncState stateService play Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::syncState currentStatus play Dec 26 15:40:29 volumio volumio[997]: info: Received an update from plugin. extracting info from payload Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:29 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:29 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:29 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:29 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:29 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched first chunk of 38, total size is 19481719 bytes" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=info msg="loaded track \"War Pigs - Charity Version\" (paused: false, position: 0ms, duration: 484779ms, prefetched: false)" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="scheduling prefetch in 455s" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="emitting websocket event: metadata" Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","name":"War Pigs - Charity Version","artist_names":["Judas Priest","Ozzy Osbourne"],"album_name":"War Pigs (Charity Version)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","position":0,"duration":484779,"release_date":"year:2025 month:9 day:26","track_number":1,"disc_number":1}} Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched chunk 3/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="emitting websocket event: playing" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="handling play player command from a9b929e1ac1b683ef64cd12831744ceee35662e8" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","resume":false,"play_origin":"go-librespot"}} Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:30 volumio volumio[997]: verbose: CURRENT POSITION 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::syncState stateService play Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::syncState currentStatus play Dec 26 15:40:30 volumio volumio[997]: info: Received an update from plugin. extracting info from payload Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","play_origin":"playlist"}} Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched chunk 1/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched chunk 2/37, size: 524288" uri="spotify:track:14M0JWFCnsKNGSvzDn0j6q" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="selected format OGG_VORBIS_320 (20e91adebd37db60900800100eda547114e2b3a9)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="requested aes key for file 20e91adebd37db60900800100eda547114e2b3a9, gid: 165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"War Pigs - Charity Version","artist":"Judas Priest, Ozzy Osbourne","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","seek":0,"duration":484,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:30 volumio volumio[997]: verbose: CURRENT POSITION 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::syncState stateService play Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::syncState currentStatus play Dec 26 15:40:30 volumio volumio[997]: info: Received an update from plugin. extracting info from payload Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:30 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:30 volumio volumio[997]: info: CorePlayQueue::getTrack 0 Dec 26 15:40:30 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched first chunk of 18, total size is 9007676 bytes" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=info msg="loaded track \"The Tide Is High - Edit\" (paused: false, position: 1ms, duration: 233893ms, prefetched: false)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="scheduling prefetch in 203s" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=trace msg="emitting websocket event: metadata" Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="sending successful reply for dealer request" Dec 26 15:40:30 volumio volumio[997]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","name":"The Tide Is High - Edit","artist_names":["Blondie"],"album_name":"Tide Is High","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","position":1,"duration":233893,"release_date":"year:1980 month:10 day:1","track_number":1,"disc_number":1}} Dec 26 15:40:30 volumio go-librespot[1256]: time="2025-12-26T15:40:30+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="emitting websocket event: playing" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="handling play player command from a9b929e1ac1b683ef64cd12831744ceee35662e8" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","resume":false,"play_origin":"playlist"}} Dec 26 15:40:31 volumio volumio[997]: info: Spotify is playing in volatile mode Dec 26 15:40:31 volumio volumio[997]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: UNSET VOLATILE Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: {"status":"play","position":0,"title":"War Pigs - Charity Version","artist":"Judas Priest","album":"War Pigs (Charity Version)","albumart":"https://i.scdn.co/image/ab67616d0000b2730aa8fb052090c291d251785d","uri":"spotify:track:14M0JWFCnsKNGSvzDn0j6q","trackType":"spotify","codec":"ogg","seek":0,"duration":484,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":30,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 26 15:40:31 volumio volumio[997]: info: Setting Spotify stop after unset volatile call Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"The Tide Is High - Edit","artist":"Blondie","album":"Tide Is High","albumart":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","trackType":"spotify","seek":1,"duration":233,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:31 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="emitting websocket event: will_play" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","play_origin":"playlist"}} Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="selected format OGG_VORBIS_320 (20e91adebd37db60900800100eda547114e2b3a9)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="requested aes key for file 20e91adebd37db60900800100eda547114e2b3a9, gid: 165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"The Tide Is High - Edit","artist":"Blondie","album":"Tide Is High","albumart":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","trackType":"spotify","seek":1,"duration":233,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:31 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="fetched first chunk of 18, total size is 9007676 bytes" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=info msg="loaded track \"The Tide Is High - Edit\" (paused: false, position: 1ms, duration: 233893ms, prefetched: false)" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio volumio[997]: info: Spotify Stop Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: SPOTIFY STOP Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: {"status":"play","title":"The Tide Is High - Edit","artist":"Blondie","album":"Tide Is High","albumart":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","trackType":"spotify","codec":"ogg","seek":1,"duration":233,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":30,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="scheduling prefetch in 203s" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="emitting websocket event: metadata" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="sending successful reply for dealer request" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","name":"The Tide Is High - Edit","artist_names":["Blondie"],"album_name":"Tide Is High","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","position":1,"duration":233893,"release_date":"year:1980 month:10 day:1","track_number":1,"disc_number":1}} Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=trace msg="emitting websocket event: playing" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E4xZNDAFEy0Ly","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","resume":false,"play_origin":"playlist"}} Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"The Tide Is High - Edit","artist":"Blondie","album":"Tide Is High","albumart":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","trackType":"spotify","seek":1,"duration":233,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:31 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:31 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:31 volumio go-librespot[1256]: time="2025-12-26T15:40:31+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:165NAtd2DRPKNQ6EVY0VG9" Dec 26 15:40:31 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:32 volumio volumio[997]: SPOTIFY: PUSH STATE SPOTIFY Dec 26 15:40:32 volumio volumio[997]: SPOTIFY: {"status":"play","service":"spop","title":"The Tide Is High - Edit","artist":"Blondie","album":"Tide Is High","albumart":"https://i.scdn.co/image/ab67616d00001e022c240cf9bee7ac86cc272c92","uri":"spotify:track:165NAtd2DRPKNQ6EVY0VG9","trackType":"spotify","seek":1,"duration":233,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 26 15:40:32 volumio volumio[997]: info: CoreCommandRouter::servicePushState Dec 26 15:40:32 volumio volumio[997]: info: CoreStateMachine::pushState Dec 26 15:40:32 volumio volumio[997]: info: CoreCommandRouter::volumioPushState Dec 26 15:40:32 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 26 15:40:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 15:40:36 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 26 15:40:38 volumio volumio[997]: info: Enabling plugin fusiondsp Dec 26 15:40:38 volumio volumio[997]: info: Loading plugin "fusiondsp"... Dec 26 15:40:39 volumio volumio[997]: info: Applying required configuration parameters for plugin fusiondsp Dec 26 15:40:39 volumio volumio[997]: info: Preparing to generate the ALSA configuration file Dec 26 15:40:39 volumio volumio[997]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 26 15:40:39 volumio volumio[997]: info: Reading ALSA contributions from plugins. Dec 26 15:40:39 volumio volumio[997]: info: Asound.conf file written Dec 26 15:40:39 volumio sudo[1907]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 26 15:40:39 volumio sudo[1907]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio sudo[1907]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio volumio[997]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy Dec 26 15:40:39 volumio volumio[997]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy Dec 26 15:40:39 volumio volumio[997]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy Dec 26 15:40:39 volumio volumio[997]: info: Output device has changed, restarting MPD Dec 26 15:40:39 volumio sudo[1912]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 15:40:39 volumio volumio[997]: info: Output device has changed, restarting Shairport Sync Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:39 volumio sudo[1912]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio sudo[1912]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio sudo[1914]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 15:40:39 volumio sudo[1914]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio systemd[1]: Stopping Music Player Daemon... Dec 26 15:40:39 volumio volumio[997]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 15:40:39 volumio volumio[997]: info: PLUGIN START: fusiondsp Dec 26 15:40:39 volumio volumio[997]: info: Loading i18n strings for locale en Dec 26 15:40:39 volumio systemd[1]: mpd.service: Succeeded. Dec 26 15:40:39 volumio systemd[1]: Stopped Music Player Daemon. Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: FusionDsp - mixtype--------------------- Hardware Dec 26 15:40:39 volumio volumio[997]: info: Preparing to generate the ALSA configuration file Dec 26 15:40:39 volumio volumio[997]: info: Done. Dec 26 15:40:39 volumio volumio[997]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 26 15:40:39 volumio volumio[997]: info: Reading ALSA contributions from plugins. Dec 26 15:40:39 volumio volumio[997]: info: MPD Permissions set Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio systemd[1]: Starting Music Player Daemon... Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 26 15:40:39 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:40:39 volumio volumio[997]: info: Asound.conf file unchanged, so no further update is needed Dec 26 15:40:39 volumio volumio[997]: info: Output device has changed, restarting MPD Dec 26 15:40:39 volumio sudo[1926]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 15:40:39 volumio sudo[1926]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio volumio[997]: info: Output device has changed, restarting Shairport Sync Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:39 volumio sudo[1928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 15:40:39 volumio sudo[1928]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 26 15:40:39 volumio sudo[1931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 15:40:39 volumio sudo[1920]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 15:40:39 volumio sudo[1920]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio sudo[1928]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio systemd[1]: shairport-sync.service: Succeeded. Dec 26 15:40:39 volumio sudo[1931]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 26 15:40:39 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 26 15:40:39 volumio sudo[1920]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio sudo[1926]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio volumio[997]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 15:40:39 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Dec 26 15:40:39 volumio systemd[1]: mpd.service: Succeeded. Dec 26 15:40:39 volumio volumio[997]: info: FusionDsp - IP adress is ---------------------------192.168.50.24 Dec 26 15:40:39 volumio systemd[1]: Stopped Music Player Daemon. Dec 26 15:40:39 volumio volumio[997]: info: FusionDsp - Dec 26 15:40:39 volumio systemd[1]: Starting Music Player Daemon... Dec 26 15:40:39 volumio sudo[1940]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 15:40:39 volumio sudo[1940]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio sudo[1940]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio volumio[997]: info: FusionDsp - undefined Dec 26 15:40:39 volumio volumio[997]: info: MPD Permissions set Dec 26 15:40:39 volumio volumio[997]: info: Shairport-Sync Started Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 15:40:39 volumio volumio[997]: info: Starting Shairport Sync Dec 26 15:40:39 volumio sudo[1950]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 15:40:39 volumio sudo[1950]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 26 15:40:39 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 26 15:40:39 volumio systemd[1]: shairport-sync.service: Succeeded. Dec 26 15:40:39 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 26 15:40:39 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 26 15:40:39 volumio sudo[1950]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:39 volumio volumio[997]: info: Shairport-Sync Started Dec 26 15:40:40 volumio mpd[1944]: Dec 26 15:40 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 15:40:40 volumio systemd[1]: Started Music Player Daemon. Dec 26 15:40:40 volumio sudo[1931]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:40 volumio sudo[1914]: pam_unix(sudo:session): session closed for user root Dec 26 15:40:40 volumio volumio[997]: error: MPD error: The expression evaluated to a falsy value: Dec 26 15:40:40 volumio volumio[997]: assert.ok(self.idling) Dec 26 15:40:40 volumio volumio[997]: error: The expression evaluated to a falsy value: Dec 26 15:40:40 volumio volumio[997]: assert.ok(self.idling) Dec 26 15:40:40 volumio volumio[997]: error: updateQueue error: null Dec 26 15:40:40 volumio go-librespot[1256]: time="2025-12-26T15:40:40+01:00" level=trace msg="sent dealer ping" Dec 26 15:40:40 volumio volumio[997]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 15:40:40 volumio volumio[997]: TypeError: Cannot read property 'off' of undefined Dec 26 15:40:40 volumio volumio[997]: at FusionDsp.onStop (/data/plugins/audio_interface/fusiondsp/index.js:107:15) Dec 26 15:40:40 volumio volumio[997]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Dec 26 15:40:40 volumio volumio[997]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) Dec 26 15:40:40 volumio volumio[997]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1556:29) Dec 26 15:40:40 volumio volumio[997]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1401:47) Dec 26 15:40:40 volumio volumio[997]: at Socket.emit (events.js:315:20) Dec 26 15:40:40 volumio volumio[997]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Dec 26 15:40:40 volumio volumio[997]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Dec 26 15:40:40 volumio volumio[997]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 15:40:40 volumio go-librespot[1256]: time="2025-12-26T15:40:40+01:00" level=trace msg="received dealer pong" Dec 26 15:40:40 volumio sudo[1967]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-26 15:39 Dec 26 15:40:40 volumio sudo[1967]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"