-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Thu 2026-08-27 13:05:29 CEST. -- Aug 27 13:05:11 sound-buero-lukas systemd-timedated[1010]: Changed local time to Thu Aug 27 13:05:11 2026 Aug 27 13:05:11 sound-buero-lukas sudo[1008]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:11 sound-buero-lukas volumio-time-update[594]: volumio-time-update-util: System time updated successfully. Aug 27 13:05:11 sound-buero-lukas systemd[1]: Starting Daily apt download activities... Aug 27 13:05:11 sound-buero-lukas systemd[1]: Started Volumio Time Update Utility. Aug 27 13:05:11 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "network"... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Refreshing Cached IP Addresses Aug 27 13:05:11 sound-buero-lukas sudo[1040]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 13:05:11 sound-buero-lukas sudo[1040]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:11 sound-buero-lukas sudo[1040]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:11 sound-buero-lukas sudo[1043]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 13:05:11 sound-buero-lukas sudo[1043]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:11 sound-buero-lukas sudo[1043]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "services"... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "volumio5onboarding"... Aug 27 13:05:11 sound-buero-lukas nmbd[723]: [2026/08/27 13:05:11.574204, 0] ../lib/util/become_daemon.c:138(daemon_ready) Aug 27 13:05:11 sound-buero-lukas nmbd[723]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "alsa_controller"... Aug 27 13:05:11 sound-buero-lukas systemd[1]: Started Samba NMB Daemon. Aug 27 13:05:11 sound-buero-lukas sudo[1053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 27 13:05:11 sound-buero-lukas sudo[1053]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:11 sound-buero-lukas systemd[1]: Starting Samba Winbind Daemon... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "wizard"... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "networkfs"... Aug 27 13:05:11 sound-buero-lukas systemd[1]: apt-daily.service: Succeeded. Aug 27 13:05:11 sound-buero-lukas systemd[1]: Started Daily apt download activities. Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Starting Udev Watcher for removable devices Aug 27 13:05:11 sound-buero-lukas sudo[1092]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=935679@Home!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.178.10/music/ /mnt/NAS/NASSRV Aug 27 13:05:11 sound-buero-lukas sudo[1092]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:11 sound-buero-lukas systemd[1]: Starting Daily apt upgrade and clean activities... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Ignoring mount for partition: boot Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Ignoring mount for partition: volumio Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Ignoring mount for partition: volumio_data Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "volumio_command_line_client"... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Plugin upnp is not enabled Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "my_music"... Aug 27 13:05:11 sound-buero-lukas volumio[973]: info: Loading plugin "mpd"... Aug 27 13:05:11 sound-buero-lukas winbindd[1054]: [2026/08/27 13:05:11.909091, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Aug 27 13:05:11 sound-buero-lukas winbindd[1054]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Aug 27 13:05:11 sound-buero-lukas winbindd[1054]: [2026/08/27 13:05:11.944600, 0] ../lib/util/become_daemon.c:138(daemon_ready) Aug 27 13:05:11 sound-buero-lukas systemd[1]: Started Samba Winbind Daemon. Aug 27 13:05:11 sound-buero-lukas winbindd[1054]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Aug 27 13:05:11 sound-buero-lukas systemd[1]: Starting Samba SMB Daemon... Aug 27 13:05:12 sound-buero-lukas kernel: Key type cifs.spnego registered Aug 27 13:05:12 sound-buero-lukas kernel: Key type cifs.idmap registered Aug 27 13:05:12 sound-buero-lukas 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. Aug 27 13:05:12 sound-buero-lukas kernel: CIFS: Attempting to mount //192.168.178.10/music Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Plugin upnp_browser is not enabled Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "alarm-clock"... Aug 27 13:05:12 sound-buero-lukas smbd[1109]: [2026/08/27 13:05:12.372915, 0] ../lib/util/become_daemon.c:138(daemon_ready) Aug 27 13:05:12 sound-buero-lukas smbd[1109]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Aug 27 13:05:12 sound-buero-lukas systemd[1]: Started Samba SMB Daemon. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Reached target Multi-User System. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Reached target Graphical Interface. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Starting Update UTMP about System Runlevel Changes... Aug 27 13:05:12 sound-buero-lukas systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Started Update UTMP about System Runlevel Changes. Aug 27 13:05:12 sound-buero-lukas systemd[1]: apt-daily-upgrade.service: Succeeded. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Started Daily apt upgrade and clean activities. Aug 27 13:05:12 sound-buero-lukas systemd[1]: Startup finished in 11.765s (kernel) + 25.582s (userspace) = 37.347s. Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Plugin airplay_emulation is not enabled Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "last_100"... Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "webradio"... Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "i2s_dacs"... Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: I2S DAC not set, start Auto-detection Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "volumiodiscovery"... Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** For more information see Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 13:05:12 sound-buero-lukas volumio[973]: *** WARNING *** For more information see Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** For more information see Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 13:05:12 sound-buero-lukas node[973]: *** WARNING *** For more information see Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Discovery: Started advertising with name: Sound-Buero-Lukas Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 13:05:12 sound-buero-lukas volumio[973]: info: Loading plugin "spop"... Aug 27 13:05:13 sound-buero-lukas volumio-remote-updater[608]: [2026-08-27 13:05:13] [connect] Successful connection Aug 27 13:05:13 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:13 sound-buero-lukas volumio[973]: info: Loading plugin "outputs"... Aug 27 13:05:13 sound-buero-lukas volumio[973]: info: Loading plugin "albumart"... Aug 27 13:05:13 sound-buero-lukas volumio[973]: info: Plugin example_plugin is not enabled Aug 27 13:05:13 sound-buero-lukas volumio[973]: info: Loading plugin "inputs"... Aug 27 13:05:13 sound-buero-lukas volumio[973]: info: Loading plugin "updater_comm"... Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Plugin mpdemulation is not enabled Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Loading plugin "rest_api"... Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Loading plugin "websocket"... Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Starting Socket.io Server version 2.3.0 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Loading i18n strings for locale de Aug 27 13:05:14 sound-buero-lukas volumio[973]: Updating browse sources language Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 13:05:14 sound-buero-lukas volumio[973]: Forking 3 albumart workers Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::initPlayerControls Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: Express server listening on port 3000 Aug 27 13:05:14 sound-buero-lukas volumio[973]: [Metrics] WebUI: 5s 305.62ms Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::resetVolumioState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::getcurrentVolume Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Volumio Network Manager: Network status updated: 2 Aug 27 13:05:14 sound-buero-lukas volumio-remote-updater[608]: [2026-08-27 13:05:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1787828713 101 Aug 27 13:05:14 sound-buero-lukas volumio[973]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Aug 27 13:05:14 sound-buero-lukas volumio[973]: Starting albumart workers Aug 27 13:05:14 sound-buero-lukas volumio[973]: Starting albumart workers Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Reloading queue from file Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::setRepeat null single undefined Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::pushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioPushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::setRandom null Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::pushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioPushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: VolumeController:: Volume=30 Mute =false Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::pushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioPushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::updateTrackBlock Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrackBlock Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 13:05:14 sound-buero-lukas volumio[973]: Starting albumart workers Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Setting Device type: Raspberry PI Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: VolumeController:: Volume=30 Mute =false Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreStateMachine::pushState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioPushState Aug 27 13:05:14 sound-buero-lukas sudo[1053]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Discovery: adding 486d8da1-091f-4933-b9e4-bdbbd492a389 Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: Discovery: Found device Sound-Buero-Lukas Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:14 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:17 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:19 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:19 sound-buero-lukas systemd[1]: systemd-fsckd.service: Succeeded. Aug 27 13:05:20 sound-buero-lukas sh[515]: timed out Aug 27 13:05:20 sound-buero-lukas dhcpcd[559]: timed out Aug 27 13:05:20 sound-buero-lukas sh[515]: dhcpcd exited Aug 27 13:05:20 sound-buero-lukas dhcpcd[559]: dhcpcd exited Aug 27 13:05:20 sound-buero-lukas sh[515]: ifup: failed to bring up eth0 Aug 27 13:05:20 sound-buero-lukas systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 27 13:05:20 sound-buero-lukas systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 27 13:05:21 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:22 sound-buero-lukas sudo[1092]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Cannot mount NAS NASSRV at system boot, trial number 1 ,retrying in 5 seconds Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Completed loading Core Plugins Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Preparing to generate the ALSA configuration file Aug 27 13:05:22 sound-buero-lukas kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Aug 27 13:05:22 sound-buero-lukas kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Asound.conf file unchanged, so no further update is needed Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Output device has changed, restarting MPD Aug 27 13:05:22 sound-buero-lukas sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 13:05:22 sound-buero-lukas sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: ___________ START PLUGINS ___________ Aug 27 13:05:22 sound-buero-lukas sudo[1249]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas sudo[1251]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 13:05:22 sound-buero-lukas sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: ControllerMpd::onStart: Initializing MPD Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Creating MPD Configuration file Aug 27 13:05:22 sound-buero-lukas sudo[1255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 27 13:05:22 sound-buero-lukas sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas sudo[1258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 13:05:22 sound-buero-lukas sudo[1258]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: [1787828722165] CoreMusicLibrary::Adding element Last_100 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: [1787828722169] CoreMusicLibrary::Adding element Webradio Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Initializing BBC Radios Aug 27 13:05:22 sound-buero-lukas sudo[1258]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas sudo[1261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 13:05:22 sound-buero-lukas sudo[1261]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas systemd[1]: Listening on mpd.socket. Aug 27 13:05:22 sound-buero-lukas systemd[1]: Starting Music Player Daemon... Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 13:05:22 sound-buero-lukas systemd[1]: Started Volumio5 Onboarding Server. Aug 27 13:05:22 sound-buero-lukas systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Aug 27 13:05:22 sound-buero-lukas systemd[1]: mpd.service: Succeeded. Aug 27 13:05:22 sound-buero-lukas systemd[1]: Stopped Music Player Daemon. Aug 27 13:05:22 sound-buero-lukas sudo[1255]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Creating Spotify config file Aug 27 13:05:22 sound-buero-lukas systemd[1]: Starting Music Player Daemon... Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas sudo[1276]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 13:05:22 sound-buero-lukas sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Volumio Calling Home Aug 27 13:05:22 sound-buero-lukas sudo[1276]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 27 13:05:22 sound-buero-lukas sudo[1276]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: MPD Permissions set Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: MPD Permissions set Aug 27 13:05:22 sound-buero-lukas volumio[973]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Spotify config file written Aug 27 13:05:22 sound-buero-lukas sudo[1288]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 27 13:05:22 sound-buero-lukas sudo[1288]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: No need to fix Spotify hosts Aug 27 13:05:22 sound-buero-lukas systemd[1]: Started go-librespot Daemon. Aug 27 13:05:22 sound-buero-lukas go-librespot[1294]: go-librespot daemon starting... Aug 27 13:05:22 sound-buero-lukas sudo[1288]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Volumio called home Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: New Spotify access tokenBQCy7W3GAE... Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 27 13:05:22 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:22.876+02:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Aug 27 13:05:22 sound-buero-lukas volumio[973]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 3 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Spotify Successfully logged in Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: [1787828722897] CoreMusicLibrary::Adding element Spotify Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 13:05:22 sound-buero-lukas volumio[973]: Cannot find translation for source Spotify Aug 27 13:05:22 sound-buero-lukas volumio[973]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 3 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Received Get System Info Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Discovery: Getting this device information Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 13:05:22 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:22.932+02:00 level=INFO msg="system info for c9c6e10e3d940fb73019b1a45042b605" deviceName=Sound-Buero-Lukas deviceVariant=volumio deviceModel= softwareVersion=3.912 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Received Get System Info Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: Discovery: Getting this device information Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 13:05:22 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 13:05:22 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:22.945+02:00 level=INFO msg="enabling local network discovery" Aug 27 13:05:22 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:22.970+02:00 level=INFO msg="enabling BLE discovery" Aug 27 13:05:23 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:23.027+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: Received Get System Info Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: Discovery: Getting this device information Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 13:05:23 sound-buero-lukas volumio-remote-updater[608]: No test mode Aug 27 13:05:23 sound-buero-lukas volumio-remote-updater[608]: No alpha test mode Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 13:05:23 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:23.148+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Aug 27 13:05:23 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:23.149+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Aug 27 13:05:23 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:23.149+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 13:05:23 sound-buero-lukas volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=info msg="running go-librespot 0.7.1" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=debug msg="app state loaded" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 13:05:23 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=info msg="zeroconf server listening on port 40963" Aug 27 13:05:23 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:23+02:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 27 13:05:23 sound-buero-lukas volumio5-onboarding[1275]: time=2026-08-27T13:05:23.917+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 27 13:05:24 sound-buero-lukas mpd[1279]: Aug 27 13:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 27 13:05:24 sound-buero-lukas systemd[1]: Started Music Player Daemon. Aug 27 13:05:24 sound-buero-lukas sudo[1261]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:24 sound-buero-lukas sudo[1251]: pam_unix(sudo:session): session closed for user root Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: Completed starting Core Plugins Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: ------------------------------------------- Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: ----- MyVolumio plugins startup ---- Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: ------------------------------------------- Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 27 13:05:24 sound-buero-lukas volumio[973]: info: MPD running with PID1279 Aug 27 13:05:24 sound-buero-lukas volumio[973]: ,establishing connection Aug 27 13:05:24 sound-buero-lukas volumio[973]: error: MPD error: The expression evaluated to a falsy value: Aug 27 13:05:24 sound-buero-lukas volumio[973]: assert.ok(self.idling) Aug 27 13:05:24 sound-buero-lukas volumio[973]: error: The expression evaluated to a falsy value: Aug 27 13:05:24 sound-buero-lukas volumio[973]: assert.ok(self.idling) Aug 27 13:05:24 sound-buero-lukas volumio[973]: error: MPD error: The expression evaluated to a falsy value: Aug 27 13:05:24 sound-buero-lukas volumio[973]: assert.ok(self.idling) Aug 27 13:05:24 sound-buero-lukas volumio[973]: error: The expression evaluated to a falsy value: Aug 27 13:05:24 sound-buero-lukas volumio[973]: assert.ok(self.idling) Aug 27 13:05:24 sound-buero-lukas volumio[973]: error: updateQueue error: null Aug 27 13:05:25 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:25 sound-buero-lukas volumio[973]: info: go-librespot daemon successfully initialized Aug 27 13:05:27 sound-buero-lukas sudo[1325]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=935679@Home!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.178.10/music/ /mnt/NAS/NASSRV Aug 27 13:05:27 sound-buero-lukas sudo[1325]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 27 13:05:27 sound-buero-lukas kernel: CIFS: Attempting to mount //192.168.178.10/music Aug 27 13:05:27 sound-buero-lukas wpa_supplicant[875]: RRM: Ignoring radio measurement request: Not RRM network Aug 27 13:05:27 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:27+02:00" level=debug msg="obtained new client token: AAEFHQoxHgpFkaVIMmIiNn7AdNEcMwM4TvuE19co7Tw7siLloi/JZdXcFbiIjR2GW/81ZVaxBfB2DmsH/EFzvVPWb83XR1YDQCOgLkF4IY2xh/iuw2cN3iGmcTBQ45vS74614Icbx7k4qrattS9RJbErkHrzxjbroaKcJR9nl7A467WwPV7AQ2LkRmn5vlaTMPaYMsah8ULXwSgDANRDXvi3xMC5QAqLtjP3ryPAgAN+3hO1bmpwEvA=" Aug 27 13:05:27 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:27+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="completed keyexchange" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="completed challenge" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=info msg="authenticated AP" username="ni******11" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=info msg="authenticated Login5" username="ni******11" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=info msg="accepted zeroconf from LN" username="ni******11" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="dealer connection opened" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="starting accesspoint recv loop" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="starting dealer recv loop" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="received accesspoint ping" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="received connection id: ZDFjOTMxNGYtOWM5...OTk1Njk0MUM1Mw==" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="received accesspoint pong ack" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="handling transfer player command from c7eb3fcc9cb76058c636190622e67e0a4cc755b7" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="resolved context of track" uri="spotify:album:0yQq0VulQR1OGkLuZZJxQy" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="fetched new page 0 with 44 items (list: 44)" uri="spotify:album:0yQq0VulQR1OGkLuZZJxQy" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="loading track (paused: true, position: 15670ms)" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="emitting websocket event: will_play" Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: Initializing connection to go-librespot Websocket Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="new websocket client" Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: Connection to go-librespot Websocket established Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 344" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="selected format OGG_VORBIS_320 (99ee8713c05859ee823fe05cb0c2f0bf5494634d)" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="requested aes key for file 99ee8713c05859ee823fe05cb0c2f0bf5494634d, gid: 1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="fetched first chunk of 24, total size is 12549200 bytes" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="seek to 15670ms (diff: 135ms, samples: 691047, bytes: 583965)" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="created new output device" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=info msg="loaded track \"Ceremonial Initiation\" (paused: true, position: 15670ms, duration: 294036ms, prefetched: false)" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="emitting websocket event: metadata" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=trace msg="emitting websocket event: active" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="sending successful reply for dealer request" Aug 27 13:05:28 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: Aligning Spotify Volume to Volumio Volume Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: CoreCommandRouter::volumioGetState Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: CorePlayQueue::getTrack 0 Aug 27 13:05:28 sound-buero-lukas volumio[973]: info: Setting Spotify Volume from Volumio: 30 Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=trace msg="emitting websocket event: paused" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="handling resume player command from c7eb3fcc9cb76058c636190622e67e0a4cc755b7" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=trace msg="seek to 15670ms (diff: 135ms, samples: 691047, bytes: 583965)" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:29 sound-buero-lukas volumio[973]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 13:05:29 sound-buero-lukas volumio[973]: TypeError: Cannot read property 'service' of undefined Aug 27 13:05:29 sound-buero-lukas volumio[973]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:345:50) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:279:18) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at WebSocket.emit (events.js:315:20) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1225:20) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver.emit (events.js:315:20) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 27 13:05:29 sound-buero-lukas volumio[973]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 27 13:05:29 sound-buero-lukas volumio[973]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02: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" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="resume track at 15535ms" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="fetched chunk 4/23, size: 524288" uri="spotify:track:1CmWIECNAzRBjyOmwP8Y7N" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=trace msg="scheduling prefetch in 248s" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="sending successful reply for dealer request" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 13:05:29 sound-buero-lukas go-librespot[1294]: time="2026-08-27T13:05:29+02:00" level=trace msg="emitting websocket event: playing" Aug 27 13:05:29 sound-buero-lukas sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-27 13:04 Aug 27 13:05:29 sound-buero-lukas sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"