Dec 08 12:45:11 volumiocasalu systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 08 12:45:11 volumiocasalu systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 08 12:45:11 volumiocasalu systemd[1]: setdatetime-helper.service: Consumed 1.041s CPU time. Dec 08 12:45:11 volumiocasalu systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Dec 08 12:45:11 volumiocasalu systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Dec 08 12:45:11 volumiocasalu systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Dec 08 12:45:11 volumiocasalu systemd[1]: e2scrub_all.service: Deactivated successfully. Dec 08 12:45:11 volumiocasalu systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Dec 08 12:45:11 volumiocasalu systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Dec 08 12:45:11 volumiocasalu winbindd[1178]: [2025/12/08 12:45:11.254536, 0] ../../source3/winbindd/winbindd_idmap.c:372(wb_parent_idmap_setup_lookupname_done) Dec 08 12:45:11 volumiocasalu winbindd[1178]: wb_parent_idmap_setup_lookupname_done: Lookup domain name 'VOLUMIOCASALU' failed 'NT_STATUS_IO_TIMEOUT' Dec 08 12:45:11 volumiocasalu systemd[1]: dpkg-db-backup.service: Deactivated successfully. Dec 08 12:45:11 volumiocasalu systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Dec 08 12:45:11 volumiocasalu systemd[1]: Started smbd.service - Samba SMB Daemon. Dec 08 12:45:11 volumiocasalu systemd[1]: Reached target multi-user.target - Multi-User System. Dec 08 12:45:11 volumiocasalu systemd[1]: Reached target graphical.target - Graphical Interface. Dec 08 12:45:11 volumiocasalu systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Dec 08 12:45:11 volumiocasalu systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Dec 08 12:45:11 volumiocasalu systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Dec 08 12:45:11 volumiocasalu systemd[1]: Startup finished in 21.559s (kernel) + 18.489s (userspace) = 40.048s. Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 83.137.41.10 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 152.53.44.250 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 91.206.8.34 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 152.53.51.182 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 2a02:1748:0:1500:3::2005 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 2001:67c:1b70:80::80:35 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 2a02:1748:0:1500:1::8002 Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: Pool taking: 2a0a:4cc0:c0:1264:c4b0:eaff:fe65:e4bf Dec 08 12:45:11 volumiocasalu ntpd[994]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Dec 08 12:45:12 volumiocasalu volumio[1110]: info: MYVOLUMIO Environment detected Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Plugin folders cleanup Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning into folder /volumio/app/plugins/ Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category audio_interface Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category miscellanea Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category music_service Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category plugins.json Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category system_controller Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category user_interface Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning into folder /data/plugins/ Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Scanning category music_service Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Plugin folders cleanup completed Dec 08 12:45:12 volumiocasalu volumio[1110]: info: ------------------------------------------- Dec 08 12:45:12 volumiocasalu volumio[1110]: info: ----- Core plugins startup ---- Dec 08 12:45:12 volumiocasalu volumio[1110]: info: ------------------------------------------- Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Loading plugins from folder /volumio/app/plugins/ Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Adding plugin upnp to MyMusic Plugins Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Loading plugins from folder /data/plugins/ Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Loading plugin "system"... Dec 08 12:45:12 volumiocasalu volumio[1110]: info: Loading plugin "appearance"... Dec 08 12:45:12 volumiocasalu volumio-remote-updater[718]: [2025-12-08 12:45:12] [connect] Successful connection Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: Pool taking: 185.144.161.170 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: Pool taking: 193.171.23.163 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: Pool taking: 81.16.47.3 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: Pool taking: 83.215.130.11 Dec 08 12:45:12 volumiocasalu ntpd[994]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: Pool skipping: 152.53.132.244 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: Pool skipping: 178.251.64.52 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: Pool taking: 162.159.200.1 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: Pool taking: 46.102.157.67 Dec 08 12:45:13 volumiocasalu ntpd[994]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Dec 08 12:45:13 volumiocasalu volumio[1110]: info: Loading plugin "network"... Dec 08 12:45:13 volumiocasalu volumio[1110]: info: Refreshing Cached IP Addresses Dec 08 12:45:14 volumiocasalu sudo[1293]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 12:45:14 volumiocasalu sudo[1293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:14 volumiocasalu sudo[1293]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "services"... Dec 08 12:45:14 volumiocasalu sudo[1296]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 12:45:14 volumiocasalu sudo[1296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "alsa_controller"... Dec 08 12:45:14 volumiocasalu sudo[1296]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:14 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "wizard"... Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "networkfs"... Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Starting Udev Watcher for removable devices Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Ignoring mount for partition: boot Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Ignoring mount for partition: volumio Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Ignoring mount for partition: volumio_data Dec 08 12:45:14 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "volumio_command_line_client"... Dec 08 12:45:14 volumiocasalu sudo[1321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=$HulleWulle22,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //10.10.10.10/music /mnt/NAS/Volumio Dec 08 12:45:14 volumiocasalu sudo[1321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "upnp"... Dec 08 12:45:14 volumiocasalu volumio[1110]: info: [1765194314306] Starting Upmpd Daemon Dec 08 12:45:14 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "my_music"... Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "mpd"... Dec 08 12:45:14 volumiocasalu kernel: netfs: FS-Cache loaded Dec 08 12:45:14 volumiocasalu kernel: Key type cifs.spnego registered Dec 08 12:45:14 volumiocasalu kernel: Key type cifs.idmap registered Dec 08 12:45:14 volumiocasalu kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Dec 08 12:45:14 volumiocasalu kernel: CIFS: Attempting to mount //10.10.10.10/music Dec 08 12:45:14 volumiocasalu sudo[1321]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:14 volumiocasalu volumio[1110]: info: Loading plugin "upnp_browser"... Dec 08 12:45:15 volumiocasalu volumio[1110]: info: Loading plugin "alarm-clock"... Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "airplay_emulation"... Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Starting Shairport Sync Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "last_100"... Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "webradio"... Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "i2s_dacs"... Dec 08 12:45:16 volumiocasalu volumio[1110]: info: I2S DAC not set, start Auto-detection Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "volumiodiscovery"... Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** For more information see Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 12:45:16 volumiocasalu volumio[1110]: *** WARNING *** For more information see Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** For more information see Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 12:45:16 volumiocasalu node[1110]: *** WARNING *** For more information see Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Discovery: Started advertising with name: VolumioCasalu Dec 08 12:45:16 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 12:45:16 volumiocasalu volumio[1110]: info: Loading plugin "soundcloud"... Dec 08 12:45:17 volumiocasalu volumio[1110]: info: Loading plugin "spop"... Dec 08 12:45:19 volumiocasalu ntpd[994]: CLOCK: time stepped by 1.143907 Dec 08 12:45:19 volumiocasalu ntpd[994]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "outputs"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "albumart"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Plugin example_plugin is not enabled Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "inputs"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "updater_comm"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Plugin mpdemulation is not enabled Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "rest_api"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading plugin "websocket"... Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Starting Socket.io Server version 1.7.4 Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Loading i18n strings for locale de Dec 08 12:45:21 volumiocasalu volumio[1110]: Updating browse sources language Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::initPlayerControls Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: Express server listening on port 3000 Dec 08 12:45:21 volumiocasalu volumio[1110]: [Metrics] WebUI: 12s 281.92ms Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreStateMachine::resetVolumioState Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreStateMachine::getcurrentVolume Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreStateMachine::pushState Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioPushState Dec 08 12:45:21 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:21 volumiocasalu volumio[1110]: info: Volumio Network Manager: Network status updated: 1 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Reloading queue from file Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreStateMachine::setRepeat null single undefined Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreStateMachine::pushState Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioPushState Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreStateMachine::setRandom true Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreStateMachine::pushState Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioPushState Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Setting Device type: Raspberry PI Dec 08 12:45:22 volumiocasalu volumio[1110]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 08 12:45:22 volumiocasalu volumio[1110]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Completed loading Core Plugins Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Preparing to generate the ALSA configuration file Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Asound.conf file unchanged, so no further update is needed Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Output device has changed, restarting MPD Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Output device has changed, restarting Shairport Sync Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:22 volumiocasalu sudo[1384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 12:45:22 volumiocasalu sudo[1384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:22 volumiocasalu sudo[1383]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: ___________ START PLUGINS ___________ Dec 08 12:45:22 volumiocasalu volumio[1110]: info: ControllerMpd::onStart: Initializing MPD Dec 08 12:45:22 volumiocasalu sudo[1383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Creating MPD Configuration file Dec 08 12:45:22 volumiocasalu sudo[1383]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 12:45:22 volumiocasalu volumio[1110]: info: [1765194322251] CoreMusicLibrary::Adding element Medienserver Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:22 volumiocasalu volumio[1359]: Forking 3 albumart workers Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:22 volumiocasalu sudo[1392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 12:45:22 volumiocasalu sudo[1392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:22 volumiocasalu sudo[1392]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:22 volumiocasalu systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 12:45:22 volumiocasalu systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 12:45:22 volumiocasalu sudo[1395]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 12:45:22 volumiocasalu sudo[1395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:22 volumiocasalu sudo[1402]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 12:45:22 volumiocasalu sudo[1402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 12:45:22 volumiocasalu sudo[1402]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:22 volumiocasalu systemd[1]: mpd.service: Deactivated successfully. Dec 08 12:45:22 volumiocasalu systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 08 12:45:22 volumiocasalu systemd[1]: mpd.socket: Deactivated successfully. Dec 08 12:45:22 volumiocasalu systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 08 12:45:22 volumiocasalu systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 08 12:45:22 volumiocasalu systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 12:45:22 volumiocasalu systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 12:45:22 volumiocasalu volumio[1110]: info: [1765194322603] CoreMusicLibrary::Adding element Last_100 Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 12:45:22 volumiocasalu volumio[1110]: info: [1765194322605] CoreMusicLibrary::Adding element Webradio Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 12:45:22 volumiocasalu sudo[1431]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 12:45:22 volumiocasalu sudo[1431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 12:45:22 volumiocasalu sudo[1437]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 08 12:45:22 volumiocasalu sudo[1431]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:22 volumiocasalu volumio[1110]: info: Initializing BBC Radios Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 12:45:22 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:23 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 12:45:23 volumiocasalu volumio[1110]: info: [1765194323094] CoreMusicLibrary::Adding element SoundCloud Dec 08 12:45:23 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:23 volumiocasalu volumio[1110]: Cannot find translation for source SoundCloud Dec 08 12:45:23 volumiocasalu volumio[1110]: info: Creating Spotify config file Dec 08 12:45:23 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:25 volumiocasalu volumio[1110]: info: Volumio Calling Home Dec 08 12:45:27 volumiocasalu mpd[1438]: 2025-12-08T12:45:27 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 08 12:45:27 volumiocasalu systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 08 12:45:27 volumiocasalu systemd[1]: Started mpd.service - Music Player Daemon. Dec 08 12:45:27 volumiocasalu sudo[1395]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:27 volumiocasalu sudo[1384]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:27 volumiocasalu volumio[1401]: Starting albumart workers Dec 08 12:45:27 volumiocasalu volumio[1404]: Starting albumart workers Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Discovery: adding 5035428c-bb55-4594-a9bd-8a2b358b8e23 Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Discovery: Found device VolumioCasalu Dec 08 12:45:28 volumiocasalu sudo[1475]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 12:45:28 volumiocasalu sudo[1475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:28 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:28 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Discovery: this is already registered, 5035428c-bb55-4594-a9bd-8a2b358b8e23 Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Discovery: Found device VolumioCasalu Dec 08 12:45:28 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:28 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:28 volumiocasalu sudo[1475]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:28 volumiocasalu sudo[1477]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 12:45:28 volumiocasalu sudo[1477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:28 volumiocasalu sudo[1477]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:28 volumiocasalu volumio[1403]: Starting albumart workers Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Completed starting Core Plugins Dec 08 12:45:28 volumiocasalu volumio[1110]: info: ------------------------------------------- Dec 08 12:45:28 volumiocasalu volumio[1110]: info: ----- MyVolumio plugins startup ---- Dec 08 12:45:28 volumiocasalu volumio[1110]: info: ------------------------------------------- Dec 08 12:45:28 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 08 12:45:28 volumiocasalu volumio[1110]: info: MPD Permissions set Dec 08 12:45:28 volumiocasalu volumio[1110]: info: MPD Permissions set Dec 08 12:45:28 volumiocasalu volumio[1110]: info: MPD running with PID1438 Dec 08 12:45:28 volumiocasalu volumio[1110]: ,establishing connection Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Volumio called home Dec 08 12:45:28 volumiocasalu volumio[1110]: info: Spotify config file written Dec 08 12:45:28 volumiocasalu sudo[1488]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 08 12:45:28 volumiocasalu sudo[1488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:28 volumiocasalu volumio-remote-updater[718]: [2025-12-08 12:45:28] [connect] Successful connection Dec 08 12:45:28 volumiocasalu systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 08 12:45:28 volumiocasalu systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 08 12:45:29 volumiocasalu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 12:45:29 volumiocasalu go-librespot[1490]: go-librespot daemon starting... Dec 08 12:45:29 volumiocasalu sudo[1488]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=info msg="running go-librespot 0.4.0" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=debug msg="app state loaded" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 08 12:45:29 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:29+01:00" level=info msg="zeroconf server listening on port 38759" Dec 08 12:45:30 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:30+01:00" level=debug msg="obtained new client token: AABRlRd2dN6v6igbkXLV9k6tayr+kWfYuCNkU88blPwLggCroPotbTbffh+qwyGoRkvdcojrm3V56H4/cqBMdqwb+XzYEpu+ujnyP+JMDl9wQhT/R4xsxmBTJW1psrl2FwKioojq31R9bxmP1Cw836uXhQSkliQDUfMXwt9EDmGAUmT94gMo26D/CMlJN4qi7LkmcQtDQ6EMNxhUp1rFh7K+L/2HbKQ8GOBinVXvOqg8Ns3L7wYt1mc=" Dec 08 12:45:30 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:30+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 08 12:45:30 volumiocasalu volumio[1110]: error: MPD error: The expression evaluated to a falsy value: Dec 08 12:45:30 volumiocasalu volumio[1110]: assert.ok(self.idling) Dec 08 12:45:30 volumiocasalu go-librespot[1491]: time="2025-12-08T12:45:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 08 12:45:30 volumiocasalu systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 12:45:30 volumiocasalu systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 12:45:30 volumiocasalu volumio[1110]: error: The expression evaluated to a falsy value: Dec 08 12:45:30 volumiocasalu volumio[1110]: assert.ok(self.idling) Dec 08 12:45:30 volumiocasalu volumio[1110]: error: MPD error: The expression evaluated to a falsy value: Dec 08 12:45:30 volumiocasalu volumio[1110]: assert.ok(self.idling) Dec 08 12:45:30 volumiocasalu volumio[1110]: error: The expression evaluated to a falsy value: Dec 08 12:45:30 volumiocasalu volumio[1110]: assert.ok(self.idling) Dec 08 12:45:30 volumiocasalu volumio[1110]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 12:45:30 volumiocasalu volumio[1110]: info: No need to fix Spotify hosts Dec 08 12:45:31 volumiocasalu volumio[1110]: error: updateQueue error: null Dec 08 12:45:31 volumiocasalu volumio-remote-updater[718]: [2025-12-08 12:45:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765194328 101 Dec 08 12:45:31 volumiocasalu volumio[1110]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Dec 08 12:45:31 volumiocasalu volumio[1110]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 12:45:31 volumiocasalu volumio[1110]: SPOTIFY: BQCKlsvuHdoJI6OiSxoVpelJo80kipkHOg0Sa6Tb5IumfkOcU3yeB8G2DAzqVKC7M9T4n5lNsu1EdcVfi4MAoIXx3vXa-QJN575i9DdQag6LIfARTzDClOQV5INbiaJ_xmuEweVg5GVhRCNGirfcLCEIRm55ecTCaZYRawDhOKauitcGAW6LDEdooBifuQn8DcfnkQQW08QDxD0q2KXuBgCsNepzFtac2_P1MofWg5WBRjLUTu8W2zUXBzmeLS5BERBuEZOqp-edFt096L_fByI2MPHVp9hFGFKurcqpwrG9U_Spob-FotCt Dec 08 12:45:31 volumiocasalu volumio[1110]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 12:45:31 volumiocasalu volumio[1110]: info: New Spotify access token = BQCKlsvuHdoJI6OiSxoVpelJo80kipkHOg0Sa6Tb5IumfkOcU3yeB8G2DAzqVKC7M9T4n5lNsu1EdcVfi4MAoIXx3vXa-QJN575i9DdQag6LIfARTzDClOQV5INbiaJ_xmuEweVg5GVhRCNGirfcLCEIRm55ecTCaZYRawDhOKauitcGAW6LDEdooBifuQn8DcfnkQQW08QDxD0q2KXuBgCsNepzFtac2_P1MofWg5WBRjLUTu8W2zUXBzmeLS5BERBuEZOqp-edFt096L_fByI2MPHVp9hFGFKurcqpwrG9U_Spob-FotCt Dec 08 12:45:31 volumiocasalu volumio[1110]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 08 12:45:31 volumiocasalu volumio[1110]: info: Starting Shairport Sync Dec 08 12:45:31 volumiocasalu volumio[1110]: info: Starting Shairport Sync Dec 08 12:45:31 volumiocasalu volumio[1110]: info: Starting Shairport Sync Dec 08 12:45:31 volumiocasalu sudo[1529]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 08 12:45:31 volumiocasalu sudo[1529]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:31 volumiocasalu sudo[1531]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 12:45:31 volumiocasalu sudo[1531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:31 volumiocasalu sudo[1533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 12:45:31 volumiocasalu sudo[1533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:31 volumiocasalu sudo[1535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 12:45:31 volumiocasalu sudo[1535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:31 volumiocasalu sudo[1538]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 12:45:31 volumiocasalu sudo[1538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:31 volumiocasalu systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 08 12:45:31 volumiocasalu systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 12:45:31 volumiocasalu systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 12:45:31 volumiocasalu systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 12:45:31 volumiocasalu systemd[1]: shairport-sync.service: Consumed 1.621s CPU time. Dec 08 12:45:31 volumiocasalu systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 12:45:31 volumiocasalu sudo[1529]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:31 volumiocasalu sudo[1531]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:31 volumiocasalu systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 08 12:45:31 volumiocasalu systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 12:45:31 volumiocasalu mpd_monitor.sh[1557]: MPD Monitor Service: Starting MPD Monitor Service Dec 08 12:45:31 volumiocasalu systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 12:45:31 volumiocasalu systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 12:45:31 volumiocasalu systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 12:45:31 volumiocasalu sudo[1533]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:31 volumiocasalu sudo[1545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 12:45:31 volumiocasalu sudo[1538]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:31 volumiocasalu sudo[1535]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:31 volumiocasalu sudo[1545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:32 volumiocasalu systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 08 12:45:32 volumiocasalu systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 08 12:45:32 volumiocasalu systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Shairport-Sync Started Dec 08 12:45:32 volumiocasalu volumio[1110]: Error adding Membership: Error: addMembership EINVAL Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Upmpdcli Daemon Started Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Shairport-Sync Started Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Shairport-Sync Started Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Successfully started MPD Monitor Dec 08 12:45:32 volumiocasalu systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 08 12:45:32 volumiocasalu sudo[1545]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:32 volumiocasalu mpd_monitor.sh[1577]: MPD Monitor Service: Starting MPD Monitor Service Dec 08 12:45:32 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:32 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Successfully started MPD Monitor Dec 08 12:45:32 volumiocasalu volumio[1110]: SPOTIFY: User informations: {"country":"AT","display_name":"Alexxx","email":"lugger.alexandra@gmail.com","explicit_content":{"filter_enabled":true,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/jbjxcacays8mupth0474a2plv"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/jbjxcacays8mupth0474a2plv","id":"jbjxcacays8mupth0474a2plv","images":[],"product":"premium","type":"user","uri":"spotify:user:jbjxcacays8mupth0474a2plv"} Dec 08 12:45:32 volumiocasalu volumio[1110]: info: Spotify Successfully logged in Dec 08 12:45:32 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 12:45:32 volumiocasalu volumio[1110]: info: [1765194332690] CoreMusicLibrary::Adding element Spotify Dec 08 12:45:32 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 12:45:32 volumiocasalu volumio[1110]: Cannot find translation for source SoundCloud Dec 08 12:45:32 volumiocasalu volumio[1110]: Cannot find translation for source Spotify Dec 08 12:45:32 volumiocasalu systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 08 12:45:32 volumiocasalu systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 08 12:45:33 volumiocasalu systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 08 12:45:33 volumiocasalu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 12:45:33 volumiocasalu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 12:45:33 volumiocasalu go-librespot[1606]: go-librespot daemon starting... Dec 08 12:45:33 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:33+01:00" level=info msg="running go-librespot 0.4.0" Dec 08 12:45:33 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:33+01:00" level=debug msg="app state loaded" Dec 08 12:45:33 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 12:45:34 volumiocasalu volumio[1110]: info: go-librespot daemon successfully initialized Dec 08 12:45:35 volumiocasalu volumio[1110]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 08 12:45:37 volumiocasalu volumio[1110]: info: Initializing connection to go-librespot Websocket Dec 08 12:45:38 volumiocasalu upmpdcli[1627]: writing RSA key Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=info msg="zeroconf server listening on port 41781" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="obtained new client token: AACTtzn+SYFVDmaeuerZvNTOc+E9peuQGpUtpDMuWoeKTOGK2QGeLhLHytf2GkztZ6tdeeFWBm7BvIxxo0DInbEHTIjKzjo97e8drHbbUNn76f4Q69e5yEXWjUe4Pm9BzNjj7HhtKnFJGFjs/Uqmc5DzGeAFgN+H48zbM3xny/D32Izrq4owNdH2XGi2a8x6+mk/xU6QdLeSG6J63ijCaoHKiib1aa9odWfizFWShr3YSw1dpPMng8JYLA==" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="completed keyexchange" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=debug msg="completed challenge" Dec 08 12:45:38 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:38+01:00" level=info msg="authenticated AP" username="jb*********************lv" Dec 08 12:45:38 volumiocasalu systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 08 12:45:38 volumiocasalu systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 08 12:45:39 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:39+01:00" level=info msg="authenticated Login5" username="jb*********************lv" Dec 08 12:45:39 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:39+01:00" level=debug msg="initializing zeroconf session" username="jb*********************lv" Dec 08 12:45:39 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:39+01:00" level=debug msg="new websocket client" Dec 08 12:45:39 volumiocasalu volumio[1110]: verbose: New Socket.io Connection to 10.10.10.90:3000 from 10.10.10.92 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 3 Dec 08 12:45:40 volumiocasalu volumio[1110]: info: Connection to go-librespot Websocket established Dec 08 12:45:41 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 12:45:41 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 12:45:41 volumiocasalu volumio[1110]: info: Discovery: Getting this device information Dec 08 12:45:41 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:41 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:41 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 12:45:42 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 12:45:42 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 12:45:42 volumiocasalu volumio[1110]: info: Discovery: Getting this device information Dec 08 12:45:42 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:42 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:42 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 12:45:42 volumiocasalu volumio[1110]: verbose: New Socket.io Connection to 10.10.10.90:3000 from 10.10.10.92 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Dec 08 12:45:43 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 08 12:45:43 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin bluetooth to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin multiroom to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin metavolumio to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin cd_controller to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 08 12:45:43 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="dealer connection opened" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=trace msg="starting accesspoint recv loop" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=trace msg="starting dealer recv loop" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=trace msg="received accesspoint ping" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="received connection id: ZTE4ZWQ0ZjItYTRh...RTIzNzdCMkUyNg==" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="update volume requested to 65535/65535" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=trace msg="received accesspoint pong ack" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 08 12:45:44 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:44+01:00" level=trace msg="emitting websocket event: volume" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="handling transfer player command from 4d1a0182d163bc4d3054ec9b7b605824767d58eb" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:1H2AhftNtx4Bk0vCXW1nRI" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=trace msg="fetched new page 0 with 45 items (list: 45)" uri="spotify:playlist:1H2AhftNtx4Bk0vCXW1nRI" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="loading track (paused: false, position: 52777ms)" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=trace msg="emitting websocket event: will_play" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="selected format OGG_VORBIS_320 (2c2f34866ad6c47e74b8188d7ed4bb2c36caf93a)" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="requested aes key for file 2c2f34866ad6c47e74b8188d7ed4bb2c36caf93a, gid: 4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1131" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=trace msg="found 3 cdn urls" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched first chunk of 15, total size is 7621100 bytes" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=trace msg="seek to 52777ms (diff: 15ms, samples: 2327465, bytes: 2399196)" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="created new output device" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu kernel: usb 1-1.2: 1:1: cannot get freq at ep 0x1 Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 08 12:45:46 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:46+01:00" level=info msg="loaded track \"In der Weihnachtsbäckerei\" (paused: false, position: 52777ms, duration: 172533ms, prefetched: false)" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:46 volumiocasalu kernel: usb 1-1.2: 1:1: cannot get freq at ep 0x1 Dec 08 12:45:46 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 08 12:45:46 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 08 12:45:46 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:46 volumiocasalu volumio[1110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 12:45:46 volumiocasalu volumio[1110]: info: Starting MyVolumio Remote Streaming Endpoints Dec 08 12:45:47 volumiocasalu volumio[1110]: info: MyVolumio login type: Token Dec 08 12:45:47 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 08 12:45:47 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=trace msg="scheduling prefetch in 90s" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=trace msg="emitting websocket event: metadata" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=trace msg="emitting websocket event: active" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=debug msg="sending successful reply for dealer request" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 08 12:45:47 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:47+01:00" level=trace msg="emitting websocket event: playing" Dec 08 12:45:49 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 08 12:45:49 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 08 12:45:49 volumiocasalu volumio[1110]: info: Streaming services startup Dec 08 12:45:49 volumiocasalu volumio[1110]: info: Starting Streaming Daemon Dec 08 12:45:49 volumiocasalu volumio[1110]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 08 12:45:49 volumiocasalu sudo[1669]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 08 12:45:49 volumiocasalu sudo[1669]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 12:45:49 volumiocasalu sudo[1669]: pam_unix(sudo:session): session closed for user root Dec 08 12:45:49 volumiocasalu volumio[1110]: info: Getting Spotify volume Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Dec 08 12:45:50 volumiocasalu volumio[1110]: info: Setting Volumio Volume from Spotify: 100 Dec 08 12:45:50 volumiocasalu volumio[1110]: info: VolumeController::SetAlsaVolume100 Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:1H2AhftNtx4Bk0vCXW1nRI","uri":"spotify:track:4GKmIIiHFUdcQYC9LwWlz4","play_origin":"playlist"}} Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4GKmIIiHFUdcQYC9LwWlz4","name":"In der Weihnachtsbäckerei","artist_names":["Simone Sommerland","Karsten Glück","Die Kita-Frösche"],"album_name":"Die 30 besten Weihnachts- Und Winterlieder","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e439b1b6997f36556b942bc9","position":52777,"duration":172533,"release_date":"year:2011 month:11 day:4","track_number":1,"disc_number":1}} Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: received: {"type":"active","data":null} Dec 08 12:45:50 volumiocasalu volumio[1110]: info: Aligning Spotify Volume to Volumio Volume Dec 08 12:45:50 volumiocasalu volumio[1110]: info: CoreCommandRouter::volumioGetState Dec 08 12:45:50 volumiocasalu volumio[1110]: info: CorePlayQueue::getTrack 0 Dec 08 12:45:50 volumiocasalu volumio[1110]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:1H2AhftNtx4Bk0vCXW1nRI","uri":"spotify:track:4GKmIIiHFUdcQYC9LwWlz4","resume":false,"play_origin":"playlist"}} Dec 08 12:45:50 volumiocasalu volumio[1110]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 12:45:50 volumiocasalu volumio[1110]: TypeError: Cannot read properties of undefined (reading 'service') Dec 08 12:45:50 volumiocasalu volumio[1110]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 08 12:45:50 volumiocasalu volumio[1110]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 08 12:45:50 volumiocasalu volumio[1110]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 08 12:45:50 volumiocasalu volumio[1110]: at WebSocket.emit (node:events:514:28) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver.emit (node:events:514:28) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 08 12:45:50 volumiocasalu volumio[1110]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 08 12:45:50 volumiocasalu volumio[1110]: at _write (node:internal/streams/writable:340:10) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Writable.write (node:internal/streams/writable:344:10) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 08 12:45:50 volumiocasalu volumio[1110]: at Socket.emit (node:events:514:28) Dec 08 12:45:50 volumiocasalu volumio[1110]: at addChunk (node:internal/streams/readable:343:12) Dec 08 12:45:50 volumiocasalu volumio[1110]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 12:45:51 volumiocasalu go-librespot[1607]: time="2025-12-08T12:45:51+01:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:4GKmIIiHFUdcQYC9LwWlz4" Dec 08 12:45:54 volumiocasalu sudo[1705]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 12:44' Dec 08 12:45:54 volumiocasalu sudo[1705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="3a3cfe435f8bb2bc94a920662e91a4ef35bc8e7c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Dec 2 11:51:19 UTC 2025" VOLUMIO_VERSION="4.072" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e5001581b220b096097cf8f46a54d4f1"