-- Logs begin at Mon 2026-06-01 23:43:26 CEST, end at Tue 2026-06-02 18:26:59 CEST. -- Jun 02 18:25:15 volumio-tom systemd-timedated[793]: Changed local time to Tue Jun 2 18:25:15 2026 Jun 02 18:25:15 volumio-tom sudo[788]: pam_unix(sudo:session): session closed for user root Jun 02 18:25:15 volumio-tom volumio-time-update[396]: volumio-time-update-util: System time updated successfully. Jun 02 18:25:15 volumio-tom systemd[1]: Started Volumio Time Update Utility. Jun 02 18:25:15 volumio-tom systemd[1]: Starting Daily apt download activities... Jun 02 18:25:15 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:25:15] [connect] Successful connection Jun 02 18:25:15 volumio-tom systemd[1]: Reached target Multi-User System. Jun 02 18:25:15 volumio-tom systemd[1]: Reached target Graphical Interface. Jun 02 18:25:15 volumio-tom systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 02 18:25:15 volumio-tom systemd[1]: Starting Daily man-db regeneration... Jun 02 18:25:15 volumio-tom systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 02 18:25:16 volumio-tom systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 02 18:25:21 volumio-tom volumio[757]: info: ------------------------------------------- Jun 02 18:25:22 volumio-tom volumio[757]: info: ----- Volumio3 ---- Jun 02 18:25:22 volumio-tom volumio[757]: info: ------------------------------------------- Jun 02 18:25:22 volumio-tom volumio[757]: info: ----- System startup ---- Jun 02 18:25:22 volumio-tom volumio[757]: info: ------------------------------------------- Jun 02 18:25:30 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:25:30] [connect] Successful connection Jun 02 18:25:35 volumio-tom systemd[1]: apt-daily.service: Succeeded. Jun 02 18:25:35 volumio-tom systemd[1]: Started Daily apt download activities. Jun 02 18:25:35 volumio-tom systemd[1]: Starting Daily apt upgrade and clean activities... Jun 02 18:25:35 volumio-tom volumio[757]: info: MYVOLUMIO Environment detected Jun 02 18:25:36 volumio-tom volumio[757]: info: Configured plugin user_interface/touch_display cannot be loaded. Removing from configuration Jun 02 18:25:36 volumio-tom systemd[1]: man-db.service: Succeeded. Jun 02 18:25:36 volumio-tom systemd[1]: Started Daily man-db regeneration. Jun 02 18:25:36 volumio-tom volumio[757]: info: Plugin folders cleanup Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning into folder /volumio/app/plugins/ Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category audio_interface Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category miscellanea Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category music_service Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category plugins.json Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category system_controller Jun 02 18:25:36 volumio-tom volumio[757]: info: Scanning category user_interface Jun 02 18:25:37 volumio-tom volumio[757]: info: Scanning into folder /data/plugins/ Jun 02 18:25:37 volumio-tom volumio[757]: info: Scanning category music_service Jun 02 18:25:37 volumio-tom volumio[757]: info: Scanning category user_interface Jun 02 18:25:37 volumio-tom volumio[757]: info: Plugin folders cleanup completed Jun 02 18:25:37 volumio-tom volumio[757]: info: ------------------------------------------- Jun 02 18:25:37 volumio-tom volumio[757]: info: ----- Core plugins startup ---- Jun 02 18:25:37 volumio-tom volumio[757]: info: ------------------------------------------- Jun 02 18:25:37 volumio-tom volumio[757]: info: Loading plugins from folder /volumio/app/plugins/ Jun 02 18:25:37 volumio-tom volumio[757]: info: Adding plugin upnp to MyMusic Plugins Jun 02 18:25:37 volumio-tom volumio[757]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 02 18:25:37 volumio-tom volumio[757]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 02 18:25:37 volumio-tom volumio[757]: info: Loading plugins from folder /data/plugins/ Jun 02 18:25:37 volumio-tom volumio[757]: info: Loading plugin "system"... Jun 02 18:25:37 volumio-tom volumio[757]: info: Loading plugin "appearance"... Jun 02 18:25:42 volumio-tom ntpd[511]: Soliciting pool server 195.201.107.151 Jun 02 18:25:43 volumio-tom ntpd[511]: Soliciting pool server 134.60.111.110 Jun 02 18:25:43 volumio-tom ntpd[511]: Soliciting pool server 188.174.253.188 Jun 02 18:25:44 volumio-tom ntpd[511]: Soliciting pool server 131.234.220.231 Jun 02 18:25:44 volumio-tom ntpd[511]: Soliciting pool server 80.153.195.191 Jun 02 18:25:44 volumio-tom ntpd[511]: Soliciting pool server 217.160.19.219 Jun 02 18:25:45 volumio-tom systemd[1]: systemd-timedated.service: Succeeded. Jun 02 18:25:45 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:25:45] [connect] Successful connection Jun 02 18:25:45 volumio-tom systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 02 18:25:45 volumio-tom systemd[1]: Started Daily apt upgrade and clean activities. Jun 02 18:25:45 volumio-tom systemd[1]: Startup finished in 23.326s (kernel) + 1min 45.540s (userspace) = 2min 8.866s. Jun 02 18:25:45 volumio-tom ntpd[511]: Soliciting pool server 213.209.109.44 Jun 02 18:25:45 volumio-tom ntpd[511]: Soliciting pool server 91.98.156.7 Jun 02 18:25:45 volumio-tom ntpd[511]: Soliciting pool server 5.45.97.204 Jun 02 18:25:46 volumio-tom ntpd[511]: Soliciting pool server 185.248.188.98 Jun 02 18:25:46 volumio-tom ntpd[511]: Soliciting pool server 31.209.85.243 Jun 02 18:25:46 volumio-tom ntpd[511]: Soliciting pool server 144.91.126.59 Jun 02 18:25:47 volumio-tom volumio[757]: info: Loading plugin "network"... Jun 02 18:25:47 volumio-tom volumio[757]: info: Refreshing Cached IP Addresses Jun 02 18:25:47 volumio-tom sudo[1279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:25:47 volumio-tom ntpd[511]: Soliciting pool server 116.203.244.102 Jun 02 18:25:47 volumio-tom ntpd[511]: Soliciting pool server 94.130.184.193 Jun 02 18:25:47 volumio-tom sudo[1279]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:25:47 volumio-tom sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:25:47 volumio-tom volumio[757]: info: Loading plugin "services"... Jun 02 18:25:47 volumio-tom sudo[1279]: pam_unix(sudo:session): session closed for user root Jun 02 18:25:47 volumio-tom sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:25:47 volumio-tom volumio[757]: info: Loading plugin "alsa_controller"... Jun 02 18:25:48 volumio-tom sudo[1281]: pam_unix(sudo:session): session closed for user root Jun 02 18:25:48 volumio-tom sudo[1291]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 02 18:25:48 volumio-tom sudo[1291]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:25:48 volumio-tom ntpd[511]: Soliciting pool server 46.224.156.215 Jun 02 18:25:48 volumio-tom ntpd[511]: Soliciting pool server 2a01:7e01::f03c:94ff:fee2:cb39 Jun 02 18:25:48 volumio-tom volumio[757]: info: Hardware Mixer selected but no Hardware mixer available, detecting default mixer Jun 02 18:25:48 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 02 18:25:48 volumio-tom volumio[757]: info: Found match in Cards Database: setting mixer undefined for card Hifiberry DAC Jun 02 18:25:49 volumio-tom volumio[757]: info: Device 2 does not have any Mixer Control Available Jun 02 18:25:49 volumio-tom volumio[757]: info: CoreCommandRouter::volumioUpdateVolumeSettings Jun 02 18:25:49 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:25:49 volumio-tom volumio[757]: info: Loading plugin "wizard"... Jun 02 18:25:49 volumio-tom volumio[757]: info: Loading plugin "networkfs"... Jun 02 18:25:49 volumio-tom volumio[757]: info: Starting Udev Watcher for removable devices Jun 02 18:25:49 volumio-tom sudo[1315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=tom,password=258/,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.2/Multimedia\\Musik /mnt/NAS/DUSK-NAS Jun 02 18:25:49 volumio-tom ntpd[511]: Soliciting pool server 85.215.189.120 Jun 02 18:25:49 volumio-tom sudo[1315]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:25:49 volumio-tom volumio[757]: info: Ignoring mount for partition: boot Jun 02 18:25:49 volumio-tom volumio[757]: info: Ignoring mount for partition: volumio Jun 02 18:25:49 volumio-tom volumio[757]: info: Ignoring mount for partition: volumio_data Jun 02 18:25:49 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:25:49 volumio-tom volumio[757]: info: Loading plugin "volumio_command_line_client"... Jun 02 18:25:49 volumio-tom volumio[757]: info: Loading plugin "upnp"... Jun 02 18:25:49 volumio-tom volumio[757]: info: [1780417549998] Starting Upmpd Daemon Jun 02 18:25:50 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:25:50 volumio-tom volumio[757]: info: Loading plugin "my_music"... Jun 02 18:25:50 volumio-tom volumio[757]: info: Loading plugin "mpd"... Jun 02 18:25:50 volumio-tom kernel: Key type cifs.spnego registered Jun 02 18:25:50 volumio-tom kernel: Key type cifs.idmap registered Jun 02 18:25:50 volumio-tom 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. Jun 02 18:25:50 volumio-tom kernel: CIFS: Attempting to mount //192.168.2.2/Multimedia/Musik Jun 02 18:25:54 volumio-tom ntpd[511]: receive: Unexpected origin timestamp 0xedc9828f.ab1375f0 does not match aorg 0000000000.00000000 from server@195.201.107.151 xmt 0xedc98292.72c10e79 Jun 02 18:25:54 volumio-tom ntpd[511]: receive: Unexpected origin timestamp 0xedc9828f.ab0ced89 does not match aorg 0000000000.00000000 from server@134.60.111.110 xmt 0xedc98292.7279868a Jun 02 18:25:54 volumio-tom ntpd[511]: receive: Unexpected origin timestamp 0xedc9828f.aaffb736 does not match aorg 0000000000.00000000 from server@131.234.220.231 xmt 0xedc98292.7364646b Jun 02 18:25:54 volumio-tom ntpd[511]: receive: Unexpected origin timestamp 0xedc9828f.aaf902fa does not match aorg 0000000000.00000000 from server@217.160.19.219 xmt 0xedc98292.732181fb Jun 02 18:25:55 volumio-tom sudo[1291]: pam_unix(sudo:session): session closed for user root Jun 02 18:25:55 volumio-tom volumio[757]: info: Loading plugin "upnp_browser"... Jun 02 18:25:56 volumio-tom sudo[1315]: pam_unix(sudo:session): session closed for user root Jun 02 18:25:57 volumio-tom volumio[757]: info: Starting UPNP Browser Jun 02 18:25:57 volumio-tom volumio[757]: info: Loading plugin "alarm-clock"... Jun 02 18:25:59 volumio-tom volumio[757]: info: Loading plugin "airplay_emulation"... Jun 02 18:25:59 volumio-tom volumio[757]: info: Starting Shairport Sync Jun 02 18:25:59 volumio-tom volumio[757]: info: Loading plugin "last_100"... Jun 02 18:25:59 volumio-tom volumio[757]: info: Loading plugin "webradio"... Jun 02 18:25:59 volumio-tom volumio[757]: info: Loading plugin "i2s_dacs"... Jun 02 18:26:00 volumio-tom volumio[757]: info: Loading plugin "volumiodiscovery"... Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** For more information see Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:26:00 volumio-tom volumio[757]: *** WARNING *** For more information see Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** For more information see Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:26:00 volumio-tom node[757]: *** WARNING *** For more information see Jun 02 18:26:00 volumio-tom volumio[757]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 02 18:26:00 volumio-tom volumio[757]: info: Discovery: Started advertising with name: Volumio-Tom Jun 02 18:26:00 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:26:00 volumio-tom volumio[757]: info: Loading plugin "spop"... Jun 02 18:26:02 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:26:02] [connect] Successful connection Jun 02 18:26:06 volumio-tom volumio[757]: info: Loading plugin "outputs"... Jun 02 18:26:06 volumio-tom volumio[757]: info: Loading plugin "albumart"... Jun 02 18:26:06 volumio-tom volumio[757]: info: Plugin example_plugin is not enabled Jun 02 18:26:06 volumio-tom volumio[757]: info: Loading plugin "inputs"... Jun 02 18:26:06 volumio-tom volumio[757]: info: Loading plugin "updater_comm"... Jun 02 18:26:08 volumio-tom volumio[757]: info: Plugin mpdemulation is not enabled Jun 02 18:26:08 volumio-tom volumio[757]: info: Loading plugin "rest_api"... Jun 02 18:26:08 volumio-tom volumio[757]: info: Loading plugin "websocket"... Jun 02 18:26:08 volumio-tom volumio[757]: info: Starting Socket.io Server version 2.3.0 Jun 02 18:26:08 volumio-tom volumio[757]: info: Loading plugin "Systeminfo"... Jun 02 18:26:10 volumio-tom volumio[757]: Forking 1 albumart workers Jun 02 18:26:13 volumio-tom volumio[757]: info: Loading plugin "lastfm"... Jun 02 18:26:17 volumio-tom volumio[757]: Starting albumart workers Jun 02 18:26:18 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:26:18] [connect] Successful connection Jun 02 18:26:18 volumio-tom volumio[757]: info: Loading i18n strings for locale de Jun 02 18:26:18 volumio-tom volumio[757]: Updating browse sources language Jun 02 18:26:18 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:20 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:26:20 volumio-tom volumio[757]: info: CoreCommandRouter::initPlayerControls Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:26:21 volumio-tom volumio[757]: Express server listening on port 3000 Jun 02 18:26:21 volumio-tom volumio[757]: [Metrics] WebUI: 65s 345.67ms Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreStateMachine::resetVolumioState Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreStateMachine::getcurrentVolume Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreStateMachine::pushState Jun 02 18:26:21 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:26:21 volumio-tom volumio[757]: info: CoreCommandRouter::volumioPushState Jun 02 18:26:22 volumio-tom volumio[757]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Jun 02 18:26:22 volumio-tom volumio[757]: info: CoreStateMachine::getcurrentVolume Jun 02 18:26:22 volumio-tom volumio[757]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:26:22 volumio-tom volumio[757]: info: CoreStateMachine::pushState Jun 02 18:26:22 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:22 volumio-tom volumio[757]: info: CoreCommandRouter::volumioPushState Jun 02 18:26:22 volumio-tom sudo[1420]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:26:22 volumio-tom sudo[1422]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:26:22 volumio-tom sudo[1420]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:22 volumio-tom sudo[1422]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:22 volumio-tom sudo[1422]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:22 volumio-tom sudo[1420]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:22 volumio-tom volumio[757]: info: Volumio Network Manager: Network status updated: 2 Jun 02 18:26:23 volumio-tom volumio[757]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jun 02 18:26:23 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:23 volumio-tom volumio[757]: info: Reloading queue from file Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreStateMachine::setRepeat null single undefined Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreStateMachine::pushState Jun 02 18:26:24 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreCommandRouter::volumioPushState Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreStateMachine::setRandom null Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreStateMachine::pushState Jun 02 18:26:24 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:24 volumio-tom volumio[757]: info: CoreCommandRouter::volumioPushState Jun 02 18:26:24 volumio-tom volumio[757]: info: Setting Device type: Raspberry PI Jun 02 18:26:24 volumio-tom volumio[757]: info: Completed loading Core Plugins Jun 02 18:26:24 volumio-tom volumio[757]: info: Preparing to generate the ALSA configuration file Jun 02 18:26:24 volumio-tom sudo[1433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 02 18:26:24 volumio-tom sudo[1433]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:25 volumio-tom systemd[1]: Started UPnP Renderer front-end to MPD. Jun 02 18:26:25 volumio-tom sudo[1433]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:25 volumio-tom volumio[757]: info: Asound.conf file unchanged, so no further update is needed Jun 02 18:26:25 volumio-tom volumio[757]: info: Output device has changed, restarting MPD Jun 02 18:26:25 volumio-tom volumio[757]: info: Output device has changed, restarting Shairport Sync Jun 02 18:26:25 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:25 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:25 volumio-tom sudo[1437]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:26:25 volumio-tom sudo[1437]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:25 volumio-tom sudo[1437]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:25 volumio-tom sudo[1439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:26:25 volumio-tom sudo[1439]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:25 volumio-tom volumio[757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 18:26:25 volumio-tom systemd[1]: Listening on mpd.socket. Jun 02 18:26:25 volumio-tom volumio[757]: info: ___________ START PLUGINS ___________ Jun 02 18:26:26 volumio-tom systemd[1]: Starting Music Player Daemon... Jun 02 18:26:26 volumio-tom volumio[757]: info: ControllerMpd::onStart: Initializing MPD Jun 02 18:26:26 volumio-tom volumio[757]: info: Creating MPD Configuration file Jun 02 18:26:26 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:26:26 volumio-tom volumio[757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:26:26 volumio-tom volumio[757]: info: [1780417586404] CoreMusicLibrary::Adding element Medienserver Jun 02 18:26:26 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:26 volumio-tom sudo[1448]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:26:26 volumio-tom sudo[1448]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:26 volumio-tom sudo[1448]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:26 volumio-tom volumio[757]: info: UPNP Browser: Client initialized successfully Jun 02 18:26:26 volumio-tom sudo[1450]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:26:26 volumio-tom sudo[1450]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:26 volumio-tom sudo[1446]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 18:26:26 volumio-tom sudo[1446]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:26 volumio-tom sudo[1446]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jun 02 18:26:26 volumio-tom sudo[1446]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:26 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:26 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:26 volumio-tom systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Jun 02 18:26:26 volumio-tom systemd[1]: mpd.service: Succeeded. Jun 02 18:26:26 volumio-tom systemd[1]: Stopped Music Player Daemon. Jun 02 18:26:27 volumio-tom systemd[1]: Starting Music Player Daemon... Jun 02 18:26:27 volumio-tom volumio[757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:27 volumio-tom sudo[1458]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 18:26:27 volumio-tom sudo[1458]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:27 volumio-tom sudo[1458]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jun 02 18:26:27 volumio-tom volumio[757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 02 18:26:27 volumio-tom sudo[1458]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:26:27 volumio-tom volumio[757]: info: [1780417587842] CoreMusicLibrary::Adding element Last_100 Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:26:27 volumio-tom volumio[757]: info: [1780417587908] CoreMusicLibrary::Adding element Webradio Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:27 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:26:28 volumio-tom volumio[757]: info: Initializing BBC Radios Jun 02 18:26:28 volumio-tom volumio[757]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Jun 02 18:26:28 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:28 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:26:28 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:28 volumio-tom volumio[757]: info: Creating Spotify config file Jun 02 18:26:28 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:29 volumio-tom volumio[757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:26:29 volumio-tom volumio[757]: info: [1780417589125] CoreMusicLibrary::Adding element LastFM Jun 02 18:26:29 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:29 volumio-tom volumio[757]: Cannot find translation for source LastFM Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] scrobbler initiated! Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] extended logging: false Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] try scrobble stream/radio plays: true Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] Configuration parameters missing: "API_KEY" "API_SECRET" "username" "authToken" Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] Left init routine Jun 02 18:26:29 volumio-tom volumio[757]: info: [LastFM] Socket already connected: false Jun 02 18:26:29 volumio-tom volumio[757]: info: Volumio Calling Home Jun 02 18:26:30 volumio-tom volumio[757]: info: [LastFM] finished init with error: Configuration parameters missing: "API_KEY" "API_SECRET" "username" "authToken" Jun 02 18:26:30 volumio-tom volumio[757]: info: Discovery: adding 6283deb7-26a8-4545-8e4f-82a76b4f91ba Jun 02 18:26:30 volumio-tom volumio[757]: info: Discovery: Found device Volumio-Tom Jun 02 18:26:30 volumio-tom volumio[757]: info: CoreCommandRouter::volumioGetState Jun 02 18:26:30 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:30 volumio-tom volumio[757]: info: Upmpdcli Daemon Started Jun 02 18:26:31 volumio-tom volumio[757]: info: MPD Permissions set Jun 02 18:26:31 volumio-tom volumio[757]: info: MPD Permissions set Jun 02 18:26:31 volumio-tom volumio[757]: info: Volumio called home Jun 02 18:26:31 volumio-tom volumio[757]: info: Spotify config file written Jun 02 18:26:31 volumio-tom sudo[1478]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 18:26:31 volumio-tom sudo[1478]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:32 volumio-tom systemd[1]: Started go-librespot Daemon. Jun 02 18:26:32 volumio-tom go-librespot[1484]: go-librespot daemon starting... Jun 02 18:26:32 volumio-tom sudo[1478]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:33 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:26:33] [connect] Successful connection Jun 02 18:26:33 volumio-tom volumio[757]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jun 02 18:26:34 volumio-tom volumio[757]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:34 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:34+02:00" level=info msg="running go-librespot 0.7.1" Jun 02 18:26:34 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:34+02:00" level=debug msg="app state loaded" Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:34 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:34 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:26:35 volumio-tom volumio[757]: info: No need to fix Spotify hosts Jun 02 18:26:38 volumio-tom volumio[757]: info: New Spotify access tokenBQDexgdPtT... Jun 02 18:26:38 volumio-tom volumio[757]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 02 18:26:38 volumio-tom volumio[757]: info: Starting Shairport Sync Jun 02 18:26:38 volumio-tom volumio[757]: info: Starting Shairport Sync Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jun 02 18:26:39 volumio-tom volumio[757]: info: Starting Shairport Sync Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=info msg="zeroconf server listening on port 36651" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="obtained new client token: AABb3YRh3zJHyO4hT0DNPHulUbnOh2JZdsWB+B/5qStT1AO/NmSiZynAQ0uM08abD+vZCmLIqb+wqo0VtmcetuvDDSPZiGawb0F2honbEiyB+JEDb50UaRQeWJuBt50Z3OUFF2ot058nWDG0hJS0Nt7PWA8cnOSryKGQqP05Ert0SoAcvPq9ecZdyE11/xKf7KzHMccoYDcQJBudA5fx6GAQ+ffBd9BEuZVZvnCV7W6JmNKAZQXqkhC0" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 02 18:26:39 volumio-tom sudo[1547]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="completed keyexchange" Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=debug msg="completed challenge" Jun 02 18:26:39 volumio-tom sudo[1547]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:39 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:39+02:00" level=info msg="authenticated AP" username="tt**sk" Jun 02 18:26:39 volumio-tom sudo[1549]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 02 18:26:39 volumio-tom sudo[1549]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:40 volumio-tom sudo[1551]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 02 18:26:40 volumio-tom sudo[1551]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=info msg="authenticated Login5" username="tt**sk" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=debug msg="initializing zeroconf session" username="tt**sk" Jun 02 18:26:40 volumio-tom volumio[757]: info: CoreCommandRouter::volumioGetState Jun 02 18:26:40 volumio-tom systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 02 18:26:40 volumio-tom systemd[1]: shairport-sync.service: Succeeded. Jun 02 18:26:40 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:40 volumio-tom systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=debug msg="dealer connection opened" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=trace msg="starting accesspoint recv loop" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=trace msg="starting dealer recv loop" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=debug msg="received connection id: ZWYyYjQ0YzItMjhj...NDYzOTk4QTMzRQ==" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=trace msg="received accesspoint ping" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 02 18:26:40 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:40+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 02 18:26:40 volumio-tom volumio[757]: info: go-librespot daemon successfully initialized Jun 02 18:26:40 volumio-tom systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 02 18:26:41 volumio-tom sudo[1547]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:41 volumio-tom sudo[1549]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:41 volumio-tom sudo[1551]: pam_unix(sudo:session): session closed for user root Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="update volume requested to 20971/65535" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=trace msg="received accesspoint pong ack" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:26:41 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:41+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:26:42 volumio-tom volumio[757]: info: Shairport-Sync Started Jun 02 18:26:42 volumio-tom volumio[757]: Error adding Membership: Error: addMembership EINVAL Jun 02 18:26:42 volumio-tom volumio[757]: info: Shairport-Sync Started Jun 02 18:26:43 volumio-tom volumio[757]: info: Spotify Successfully logged in Jun 02 18:26:44 volumio-tom volumio[757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:26:44 volumio-tom volumio[757]: info: [1780417604044] CoreMusicLibrary::Adding element Spotify Jun 02 18:26:44 volumio-tom volumio[757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:26:44 volumio-tom volumio[757]: Cannot find translation for source LastFM Jun 02 18:26:44 volumio-tom volumio[757]: Cannot find translation for source Spotify Jun 02 18:26:44 volumio-tom volumio[757]: info: Initializing connection to go-librespot Websocket Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="handling transfer player command from 3558bd46e8eedebb007cf30e9add01caab5aba09" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="resolved context of track" uri="spotify:station:track:2RETchtst6lwpgfHy7CCoT" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:2RETchtst6lwpgfHy7CCoT" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="loading track (paused: true, position: 220220ms)" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1387" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:26:44 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=trace msg="emitting websocket event: will_play" Jun 02 18:26:45 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:44+02:00" level=debug msg="new websocket client" Jun 02 18:26:45 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 167" Jun 02 18:26:45 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:45+02:00" level=debug msg="selected format OGG_VORBIS_320 (9c947fabcbd4237aee340a5e7c3e265a5248e8d7)" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:45 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:45+02:00" level=debug msg="requested aes key for file 9c947fabcbd4237aee340a5e7c3e265a5248e8d7, gid: 3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:45 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:45+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:45 volumio-tom volumio[757]: info: Connection to go-librespot Websocket established Jun 02 18:26:46 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:46+02:00" level=debug msg="fetched first chunk of 20, total size is 9977068 bytes" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:47 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:47+02:00" level=debug msg="fetched chunk 19/19, size: 15596" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:48 volumio-tom volumio-remote-updater[393]: [2026-06-02 18:26:48] [connect] Successful connection Jun 02 18:26:49 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:49+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="fetched chunk 18/19, size: 524288" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=trace msg="seek to 220220ms (diff: 94ms, samples: 9711702, bytes: 9619180)" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="created new output device" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=info msg="loaded track \"Sophia Loren\" (paused: true, position: 220220ms, duration: 229828ms, prefetched: false)" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:50 volumio-tom volumio[757]: info: Getting Spotify volume Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=trace msg="emitting websocket event: metadata" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=trace msg="emitting websocket event: active" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 02 18:26:50 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:50+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Jun 02 18:26:51 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:26:51 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:51+02:00" level=trace msg="emitting websocket event: paused" Jun 02 18:26:51 volumio-tom volumio[757]: info: Aligning Spotify Volume to Volumio Volume Jun 02 18:26:51 volumio-tom volumio[757]: info: CoreCommandRouter::volumioGetState Jun 02 18:26:51 volumio-tom volumio[757]: info: CorePlayQueue::getTrack 0 Jun 02 18:26:51 volumio-tom volumio[757]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 18:26:51 volumio-tom volumio[757]: TypeError: Cannot read property 'service' of undefined Jun 02 18:26:51 volumio-tom volumio[757]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:345:50) Jun 02 18:26:51 volumio-tom volumio[757]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:279:18) Jun 02 18:26:51 volumio-tom volumio[757]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Jun 02 18:26:51 volumio-tom volumio[757]: at WebSocket.emit (events.js:315:20) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1225:20) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.emit (events.js:315:20) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 02 18:26:51 volumio-tom volumio[757]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 02 18:26:51 volumio-tom volumio[757]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 02 18:26:51 volumio-tom volumio[757]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1360:35) Jun 02 18:26:51 volumio-tom volumio[757]: at Socket.emit (events.js:315:20) Jun 02 18:26:51 volumio-tom volumio[757]: at addChunk (internal/streams/readable.js:309:12) Jun 02 18:26:51 volumio-tom volumio[757]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 02 18:26:51 volumio-tom volumio[757]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 18:26:54 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:54+02:00" level=debug msg="handling resume player command from 3558bd46e8eedebb007cf30e9add01caab5aba09" Jun 02 18:26:54 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:54+02:00" level=trace msg="seek to 220220ms (diff: 94ms, samples: 9711702, bytes: 9619180)" uri="spotify:track:3CKEAKA3eIjckfJjnvJD0h" Jun 02 18:26:54 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:54+02: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" Jun 02 18:26:54 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:54+02:00" level=debug msg="resume track at 220126ms" Jun 02 18:26:54 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=trace msg="prefetch as soon as possible" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=debug msg="prefetching next track" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=debug msg="selected format OGG_VORBIS_320 (007c419b64246404b5751bbf08aa6c59d3e8e34e)" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=debug msg="requested aes key for file 007c419b64246404b5751bbf08aa6c59d3e8e34e, gid: 1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:55 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:55+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:56 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:56+02:00" level=debug msg="fetched first chunk of 13, total size is 6701243 bytes" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:57 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:57+02:00" level=info msg="prefetched track \"HURENSOHN\" (duration: 154493ms)" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:58 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:58+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:26:58 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:58+02:00" level=trace msg="emitting websocket event: playing" Jun 02 18:26:58 volumio-tom mpd[1463]: Jun 02 18:26 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 02 18:26:59 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:59+02:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:26:59 volumio-tom sudo[1595]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-06-02 18:25 Jun 02 18:26:59 volumio-tom sudo[1595]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:26:59 volumio-tom go-librespot[1484]: time="2026-06-02T18:26:59+02:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" Jun 02 18:27:00 volumio-tom go-librespot[1484]: time="2026-06-02T18:27:00+02:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:1wsndzfARmcXLntwDwGAQu" 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="49c352e1d55e9b76c3bd7b0e3940507619bf455a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="1d32690fc900ac8c739e7eabd35ed0f570899eb8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 19 Dec 2025 02:07:26 PM CET" VOLUMIO_VERSION="3.887" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8f8c1d964af93dfdda0f02ac4140eec2"