Jun 01 11:59:43 musikserver-matthias ntpd[973]: CLOCK: time stepped by 399571.858616 Jun 01 11:59:43 musikserver-matthias ntpd[973]: CLOCK: time changed from 2026-05-27 to 2026-06-01 Jun 01 11:59:43 musikserver-matthias ntpd[973]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Jun 01 11:59:44 musikserver-matthias volumio[1148]: info: Loading plugin "appearance"... Jun 01 11:59:44 musikserver-matthias systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Jun 01 11:59:44 musikserver-matthias systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Jun 01 11:59:44 musikserver-matthias systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Jun 01 11:59:44 musikserver-matthias systemd[1]: e2scrub_all.service: Deactivated successfully. Jun 01 11:59:44 musikserver-matthias systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Jun 01 11:59:44 musikserver-matthias systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Jun 01 11:59:44 musikserver-matthias systemd[1]: dpkg-db-backup.service: Deactivated successfully. Jun 01 11:59:44 musikserver-matthias systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Jun 01 11:59:44 musikserver-matthias systemd[1]: systemd-fsckd.service: Deactivated successfully. Jun 01 11:59:45 musikserver-matthias sh[659]: timed out Jun 01 11:59:45 musikserver-matthias dhcpcd[677]: timed out Jun 01 11:59:46 musikserver-matthias sh[608]: ifup: failed to bring up eth0 Jun 01 11:59:46 musikserver-matthias systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:59:46 musikserver-matthias systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "network"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Refreshing Cached IP Addresses Jun 01 11:59:47 musikserver-matthias sudo[1383]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 11:59:47 musikserver-matthias sudo[1383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 11:59:47 musikserver-matthias sudo[1383]: pam_unix(sudo:session): session closed for user root Jun 01 11:59:47 musikserver-matthias sudo[1385]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 11:59:47 musikserver-matthias sudo[1385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "services"... Jun 01 11:59:47 musikserver-matthias sudo[1385]: pam_unix(sudo:session): session closed for user root Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "volumio5onboarding"... Jun 01 11:59:47 musikserver-matthias sudo[1395]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 11:59:47 musikserver-matthias sudo[1395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "alsa_controller"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "wizard"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "networkfs"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Starting Udev Watcher for removable devices Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Ignoring mount for partition: boot Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Ignoring mount for partition: volumio Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Ignoring mount for partition: volumio_data Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "volumio_command_line_client"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "upnp"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: [1780307987978] Starting Upmpd Daemon Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "my_music"... Jun 01 11:59:47 musikserver-matthias volumio[1148]: info: Loading plugin "mpd"... Jun 01 11:59:48 musikserver-matthias sudo[1395]: pam_unix(sudo:session): session closed for user root Jun 01 11:59:48 musikserver-matthias volumio[1148]: info: Loading plugin "upnp_browser"... Jun 01 11:59:49 musikserver-matthias systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jun 01 11:59:50 musikserver-matthias systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Jun 01 11:59:50 musikserver-matthias systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Jun 01 11:59:50 musikserver-matthias systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Jun 01 11:59:50 musikserver-matthias systemd[1]: systemd-hostnamed.service: Deactivated successfully. Jun 01 11:59:50 musikserver-matthias upmpdcli[1429]: Could not open config: /tmp/upmpdcli.conf Jun 01 11:59:50 musikserver-matthias systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:59:50 musikserver-matthias systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Jun 01 11:59:51 musikserver-matthias systemd[1]: setdatetime-helper.service: Deactivated successfully. Jun 01 11:59:51 musikserver-matthias systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jun 01 11:59:51 musikserver-matthias systemd[1]: setdatetime-helper.service: Consumed 1.124s CPU time. Jun 01 11:59:51 musikserver-matthias volumio[1148]: info: Starting UPNP Browser Jun 01 11:59:51 musikserver-matthias volumio[1148]: info: Loading plugin "alarm-clock"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "airplay_emulation"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Starting Shairport Sync Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "last_100"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "webradio"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "i2s_dacs"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "volumiodiscovery"... Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** For more information see Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 11:59:52 musikserver-matthias volumio[1148]: *** WARNING *** For more information see Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** For more information see Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 11:59:52 musikserver-matthias node[1148]: *** WARNING *** For more information see Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Discovery: Started advertising with name: Musikserver Matthias Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 11:59:52 musikserver-matthias volumio[1148]: info: Loading plugin "spop"... Jun 01 11:59:52 musikserver-matthias nmbd[1023]: [2026/06/01 11:59:52.936540, 0] ../../source3/nmbd/nmbd_nameregister.c:73(register_name_response) Jun 01 11:59:52 musikserver-matthias nmbd[1023]: register_name_response: Answer name <00> differs from question name <00>. Jun 01 11:59:52 musikserver-matthias nmbd[1023]: [2026/06/01 11:59:52.937000, 0] ../../source3/nmbd/nmbd_nameregister.c:73(register_name_response) Jun 01 11:59:52 musikserver-matthias nmbd[1023]: register_name_response: Answer name <03> differs from question name <03>. Jun 01 11:59:52 musikserver-matthias nmbd[1023]: [2026/06/01 11:59:52.937315, 0] ../../source3/nmbd/nmbd_nameregister.c:73(register_name_response) Jun 01 11:59:52 musikserver-matthias nmbd[1023]: register_name_response: Answer name <20> differs from question name <20>. Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "outputs"... Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "albumart"... Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Plugin example_plugin is not enabled Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "inputs"... Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "updater_comm"... Jun 01 11:59:56 musikserver-matthias volumio-remote-updater[734]: [2026-06-01 11:59:56] [connect] Successful connection Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Plugin mpdemulation is not enabled Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "rest_api"... Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "websocket"... Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Starting Socket.io Server version 1.7.4 Jun 01 11:59:56 musikserver-matthias volumio[1148]: info: Loading plugin "Systeminfo"... Jun 01 11:59:58 musikserver-matthias volumio[1446]: Forking 3 albumart workers Jun 01 11:59:58 musikserver-matthias volumio[1148]: info: Loading i18n strings for locale de Jun 01 11:59:58 musikserver-matthias volumio[1148]: Updating browse sources language Jun 01 11:59:58 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 11:59:59 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::initPlayerControls Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:00:00 musikserver-matthias volumio[1148]: Express server listening on port 3000 Jun 01 12:00:00 musikserver-matthias volumio[1148]: [Metrics] WebUI: 20s 147.82ms Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreStateMachine::resetVolumioState Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreStateMachine::getcurrentVolume Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreStateMachine::pushState Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioPushState Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: Cannot read play queue from file Jun 01 12:00:00 musikserver-matthias sudo[1504]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 12:00:00 musikserver-matthias sudo[1504]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:00 musikserver-matthias sudo[1504]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:00 musikserver-matthias sudo[1506]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 12:00:00 musikserver-matthias sudo[1506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:00 musikserver-matthias volumio[1148]: info: Volumio Network Manager: Network status updated: 2 Jun 01 12:00:00 musikserver-matthias sudo[1506]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:01 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreStateMachine::setRepeat null single undefined Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreStateMachine::pushState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioPushState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreStateMachine::setRandom null Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreStateMachine::pushState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioPushState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: Setting Device type: Raspberry PI Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: Completed loading Core Plugins Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: Preparing to generate the ALSA configuration file Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:02 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:03 musikserver-matthias sudo[1517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 12:00:03 musikserver-matthias sudo[1517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:03 musikserver-matthias volumio[1148]: verbose: New Socket.io Connection to 192.168.178.222:3000 from 192.168.178.76 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 1 Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: Discovery: adding 8ce99b3c-65b6-422e-a068-33417e867e31 Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: Discovery: Found device Musikserver Matthias Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: Asound.conf file unchanged, so no further update is needed Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: Output device has changed, restarting MPD Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: Output device has changed, restarting Shairport Sync Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:03 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:03 musikserver-matthias sudo[1520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 12:00:03 musikserver-matthias sudo[1520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:03 musikserver-matthias sudo[1520]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:03 musikserver-matthias sudo[1522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 12:00:03 musikserver-matthias sudo[1522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: ___________ START PLUGINS ___________ Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: ControllerMpd::onStart: Initializing MPD Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: Creating MPD Configuration file Jun 01 12:00:04 musikserver-matthias sudo[1530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 01 12:00:04 musikserver-matthias systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 12:00:04 musikserver-matthias systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: [1780308004313] CoreMusicLibrary::Adding element Medienserver Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:00:04 musikserver-matthias sudo[1530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:04 musikserver-matthias sudo[1532]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 12:00:04 musikserver-matthias sudo[1532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:04 musikserver-matthias sudo[1536]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 12:00:04 musikserver-matthias sudo[1532]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:04 musikserver-matthias sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 12:00:04 musikserver-matthias sudo[1539]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jun 01 12:00:04 musikserver-matthias sudo[1536]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:04 musikserver-matthias sudo[1535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 12:00:04 musikserver-matthias sudo[1535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: UPNP Browser: Client initialized successfully Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:04 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:04 musikserver-matthias systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Jun 01 12:00:04 musikserver-matthias systemd[1]: mpd.service: Deactivated successfully. Jun 01 12:00:04 musikserver-matthias systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 12:00:04 musikserver-matthias systemd[1]: mpd.socket: Deactivated successfully. Jun 01 12:00:04 musikserver-matthias systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 12:00:04 musikserver-matthias systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 12:00:04 musikserver-matthias systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 12:00:04 musikserver-matthias systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 12:00:04 musikserver-matthias sudo[1530]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:05 musikserver-matthias sudo[1545]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 12:00:05 musikserver-matthias sudo[1545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 12:00:05 musikserver-matthias sudo[1549]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jun 01 12:00:05 musikserver-matthias sudo[1545]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:05 musikserver-matthias systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: [1780308005532] CoreMusicLibrary::Adding element Last_100 Jun 01 12:00:05 musikserver-matthias systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: [1780308005590] CoreMusicLibrary::Adding element Webradio Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 12:00:05 musikserver-matthias systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Jun 01 12:00:05 musikserver-matthias sudo[1517]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:05 musikserver-matthias volumio[1148]: info: Initializing BBC Radios Jun 01 12:00:06 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:06.337+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Jun 01 12:00:06 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 12:00:06 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:06 musikserver-matthias volumio[1148]: info: Creating Spotify config file Jun 01 12:00:06 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:08 musikserver-matthias volumio[1471]: Starting albumart workers Jun 01 12:00:09 musikserver-matthias volumio[1472]: Starting albumart workers Jun 01 12:00:09 musikserver-matthias volumio[1470]: Starting albumart workers Jun 01 12:00:10 musikserver-matthias volumio[1148]: info: Volumio Calling Home Jun 01 12:00:11 musikserver-matthias volumio-remote-updater[734]: [2026-06-01 12:00:11] [connect] Successful connection Jun 01 12:00:13 musikserver-matthias volumio[1148]: info: Discovery: this is already registered, 8ce99b3c-65b6-422e-a068-33417e867e31 Jun 01 12:00:13 musikserver-matthias volumio[1148]: info: Discovery: Found device Musikserver Matthias Jun 01 12:00:13 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:13 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:14 musikserver-matthias volumio[1148]: info: MPD Permissions set Jun 01 12:00:14 musikserver-matthias volumio[1148]: info: MPD Permissions set Jun 01 12:00:14 musikserver-matthias volumio[1148]: info: Upmpdcli Daemon Started Jun 01 12:00:14 musikserver-matthias volumio[1148]: 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: 1 Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: Volumio called home Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: Spotify config file written Jun 01 12:00:15 musikserver-matthias sudo[1616]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 12:00:15 musikserver-matthias sudo[1616]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:15 musikserver-matthias systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 12:00:15 musikserver-matthias systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 12:00:15 musikserver-matthias systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 12:00:15 musikserver-matthias go-librespot[1619]: go-librespot daemon starting... Jun 01 12:00:15 musikserver-matthias sudo[1616]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:15 musikserver-matthias volumio[1148]: 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: 1 Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: Received Get System Info Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:15 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:15 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:15.882+02:00 level=INFO msg="system info for 01a526c476295ee0ccad662aa49e4b2b" deviceName="Musikserver Matthias" deviceVariant=volumio deviceModel= softwareVersion=4.119 Jun 01 12:00:15 musikserver-matthias volumio-remote-updater[734]: [2026-06-01 12:00:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1780308011 101 Jun 01 12:00:15 musikserver-matthias volumio[1148]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Jun 01 12:00:15 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:15.995+02:00 level=INFO msg="bootstrapping state" hasInternet=true Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: No need to fix Spotify hosts Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: Received Get System Info Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:16 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:16 musikserver-matthias volumio[1148]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jun 01 12:00:17 musikserver-matthias volumio-remote-updater[734]: Test mode disabled Jun 01 12:00:17 musikserver-matthias volumio-remote-updater[734]: Alpha mode disabled Jun 01 12:00:17 musikserver-matthias volumio-remote-updater[734]: Alpha legacy test mode disabled Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: New Spotify access tokenBQDep-Zyto... Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Starting Shairport Sync Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Starting Shairport Sync Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Starting Shairport Sync Jun 01 12:00:17 musikserver-matthias sudo[1655]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 12:00:17 musikserver-matthias sudo[1655]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 12:00:17 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:17.584+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" Jun 01 12:00:17 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:17.585+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" Jun 01 12:00:17 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:17.586+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" Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 12:00:17 musikserver-matthias sudo[1651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 12:00:17 musikserver-matthias sudo[1651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:17 musikserver-matthias sudo[1653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 12:00:17 musikserver-matthias sudo[1653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 12:00:17 musikserver-matthias systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 12:00:17 musikserver-matthias systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 12:00:17 musikserver-matthias systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 12:00:17 musikserver-matthias systemd[1]: shairport-sync.service: Consumed 1.392s CPU time. Jun 01 12:00:17 musikserver-matthias systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 12:00:17 musikserver-matthias sudo[1651]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:17 musikserver-matthias sudo[1653]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:17 musikserver-matthias sudo[1655]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Received Get System Info Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:17 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: Shairport-Sync Started Jun 01 12:00:18 musikserver-matthias volumio[1148]: Error adding Membership: Error: addMembership EINVAL Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: Shairport-Sync Started Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 12:00:18 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:18.139+02:00 level=INFO msg="enabling local network discovery" Jun 01 12:00:18 musikserver-matthias mpd[1550]: 2026-06-01T12:00:18 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 12:00:18 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:18.168+02:00 level=INFO msg="enabling BLE discovery" Jun 01 12:00:18 musikserver-matthias systemd[1]: Started mpd.service - Music Player Daemon. Jun 01 12:00:18 musikserver-matthias sudo[1535]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:18 musikserver-matthias sudo[1522]: pam_unix(sudo:session): session closed for user root Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: Shairport-Sync Started Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: Completed starting Core Plugins Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: ------------------------------------------- Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: ----- MyVolumio plugins startup ---- Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: ------------------------------------------- Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:18 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=info msg="running go-librespot 0.7.1" Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=debug msg="app state loaded" Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.236+02:00 level=INFO msg="service successfully established" component=discovery/localnet Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.486+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.178.76:53938 Jun 01 12:00:19 musikserver-matthias volumio[1148]: error: MPD error: The expression evaluated to a falsy value: Jun 01 12:00:19 musikserver-matthias volumio[1148]: assert.ok(self.idling) Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.518+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.178.76:53938 @ 0x20b6810" latency=20.085562ms platform=PLATFORM_ANDROID version=5.260413.0 Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.540+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.178.76:53938 @ 0x20b6810" latency=40.090614ms timeout=10s Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.540+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" Jun 01 12:00:19 musikserver-matthias volumio[1148]: error: The expression evaluated to a falsy value: Jun 01 12:00:19 musikserver-matthias volumio[1148]: assert.ok(self.idling) Jun 01 12:00:19 musikserver-matthias volumio[1148]: error: updateQueue error: null Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 12:00:19 musikserver-matthias bluealsa[907]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_F9_56_C5_2E_C7, ...) Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: Received Get System Info Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.679+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" name="Musikserver Matthias" Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.684+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" language=de Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: MPD running with PID1550 Jun 01 12:00:19 musikserver-matthias volumio[1148]: ,establishing connection Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.772+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" timezone=Europe/Berlin Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.774+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" available=true connected=false macAddress= ip4Address= ip6Address= Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.780+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" available=true connected=true macAddress=b8:27:eb:51:38:74 ip4Address=192.168.178.222/24 ip6Address= ssid="Obi-Lan Kenobi Mtfbwy" Jun 01 12:00:19 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:19.781+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" setupComplete=true Jun 01 12:00:19 musikserver-matthias volumio[1148]: error: updateQueue error: null Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+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 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+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 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+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 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=info msg="zeroconf server listening on port 35925" Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:00:19 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 01 12:00:19 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:19+02:00" level=debug msg="obtained new client token: AAAyZE6QlVVtRFpcFo5unWo/kfgPzbaKGqPF0a5QGqPsrtABsQQCBdM0lEMJES+MB9G1k/H5ZDmtqi6Wk702zQxlRIydwl3/Zr4YeqAmS0eBSoUmYg3P0jHUzIJj5+O4S4iESor0sO49pONi6K/cbYLBMsvE3aeLJv8/SZz9MVYHgltDQY1sLMNZHSbKfgalUPH6rAq6rI2uOWzT0mGnmNPSKYufNkfom8vBaozBiCNBn0KioLi0Ce8=" Jun 01 12:00:20 musikserver-matthias volumio[1148]: amixer -c 0 info | grep "bcm2835 ALSA" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="completed keyexchange" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="completed challenge" Jun 01 12:00:20 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:20.092+02:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.178.76:53938 error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 01 12:00:20 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:20.092+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.178.76:53938 Jun 01 12:00:20 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:20.093+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.178.76:53938 Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=info msg="authenticated AP" username="fe*********************xx" Jun 01 12:00:20 musikserver-matthias volumio[1148]: amixer -c 1 info | grep "bcm2835 Headphones" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=info msg="authenticated Login5" username="fe*********************xx" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="initializing zeroconf session" username="fe*********************xx" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="dealer connection opened" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=trace msg="starting accesspoint recv loop" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=trace msg="starting dealer recv loop" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=trace msg="received accesspoint ping" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="received connection id: NjdkMDhmNTctNmI5...MjIxNTRBODhDMA==" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=trace msg="received accesspoint pong ack" Jun 01 12:00:20 musikserver-matthias volumio[1148]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Jun 01 12:00:20 musikserver-matthias volumio[1148]: amixer -c 3 info | grep "snd_rpi_hifiberry_dac" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="update volume requested to 65535/65535" Jun 01 12:00:20 musikserver-matthias volumio[1148]: Card sysdefault:3 'sndrpihifiberry'/'snd_rpi_hifiberry_dac' Jun 01 12:00:20 musikserver-matthias volumio[1148]: info: go-librespot daemon successfully initialized Jun 01 12:00:20 musikserver-matthias volumio[1148]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Jun 01 12:00:20 musikserver-matthias volumio[1148]: /bin/sh: 1: /usr/local/bin/alsacap: not found Jun 01 12:00:20 musikserver-matthias volumio[1148]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Jun 01 12:00:20 musikserver-matthias volumio[1148]: amixer -c 2 info | grep "vc4-hdmi" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 01 12:00:20 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:20+02:00" level=trace msg="emitting websocket event: volume" Jun 01 12:00:20 musikserver-matthias volumio[1148]: Card sysdefault:2 'vc4hdmi'/'vc4-hdmi' Jun 01 12:00:20 musikserver-matthias volumio[1148]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 3 Jun 01 12:00:20 musikserver-matthias volumio[1148]: /bin/sh: 1: /usr/local/bin/alsacap: not found Jun 01 12:00:20 musikserver-matthias volumio[1148]: {"cmd":"/usr/local/bin/alsacap -C 3","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 3\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Jun 01 12:00:20 musikserver-matthias volumio[1148]: amixer -c 3 info | grep "HiFiBerry DAC" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.024+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" selectedOutputId=3 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.025+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_AUDIO_OUTPUTS_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: Received Get System Info Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: Discovery: Getting this device information Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.050+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" currentVersion=4.119 latestVersion=4.119 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.050+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_SOFTWARE_INFO_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.050+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.178.76:53938 @ 0x20b6810" status=UPDATE_STATUS_NONE progress=0 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.050+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_SOFTWARE_UPDATE_PROGRESS error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.051+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" userId= Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.051+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_USER_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.051+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" providers=3 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.051+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_MUSIC_PROVIDERS_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.133+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" plugins=0 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.134+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_PLUGINS_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.195+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" state=STATUS_STOPPED positionMs=0 volume=100 Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.195+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.195+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.76:53938 @ 0x20b6810" id= title= Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.196+02:00 level=ERROR msg="failed to send event" component=server dst=" @ 0x20b6810" event=SERVER_EVENT_TYPE_PLAYER_METADATA_CHANGED error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio5-onboarding[1542]: time=2026-06-01T12:00:21.196+02:00 level=ERROR msg="failed to send response" component=server dst=" @ 0x20b6810" id=2033104223 status=STATUS_OK error="no addresses to write to" Jun 01 12:00:21 musikserver-matthias volumio[1148]: SPOTIFY: User informations: {"account_id":"9tPnYfkWO0","country":"DE","display_name":"Mitti","email":"matthias@mittermeiernet.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/fe28qcc4km6ndbi9kzan0azxx"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/fe28qcc4km6ndbi9kzan0azxx","id":"fe28qcc4km6ndbi9kzan0azxx","images":[],"product":"premium","type":"user","uri":"spotify:user:fe28qcc4km6ndbi9kzan0azxx"} Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: Spotify Successfully logged in Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: [1780308021480] CoreMusicLibrary::Adding element Spotify Jun 01 12:00:21 musikserver-matthias volumio[1148]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:00:21 musikserver-matthias volumio[1148]: Cannot find translation for source Spotify Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="handling transfer player command from 3c2169f5ba4773f98605b9ae83bd8df100829596" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="resolved context of track" uri="spotify:collection:podcasts:episodes" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=trace msg="fetched new page 0 with 4 items (list: 4)" uri="spotify:collection:podcasts:episodes" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="loading episode (paused: true, position: 1240949ms)" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=trace msg="emitting websocket event: will_play" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="selected format OGG_VORBIS_96 (e219abdee5251dab303ed9a2486de123395c1fbf)" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="requested aes key for file e219abdee5251dab303ed9a2486de123395c1fbf, gid: 51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=trace msg="found 2 cdn urls" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:22 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:22+02:00" level=debug msg="fetched first chunk of 57, total size is 29423331 bytes" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:23 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jun 01 12:00:23 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:23+02:00" level=debug msg="fetched chunk 2/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:23 musikserver-matthias volumio[1148]: info: Initializing connection to go-librespot Websocket Jun 01 12:00:23 musikserver-matthias volumio[1148]: info: Connection to go-librespot Websocket established Jun 01 12:00:23 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:23+02:00" level=debug msg="new websocket client" Jun 01 12:00:23 musikserver-matthias volumio[1148]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 12:00:23 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1489" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1253" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 23/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 3/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 21/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 1/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 20/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=trace msg="seek to 1240949ms (diff: 628ms, samples: 54725850, bytes: 10527838)" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="created new output device" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=info msg="loaded episode \"GAG557: HB06 – Ada Blackjack, einsame Heldin der Arktis & Inselverzwergung im Dinosaurierland und albanische Abenteuer\" (paused: true, position: 1240949ms, duration: 3472169ms, prefetched: false)" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="fetched chunk 22/56, size: 524288" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=trace msg="emitting websocket event: metadata" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=trace msg="emitting websocket event: active" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="sending successful reply for dealer request" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 01 12:00:24 musikserver-matthias volumio[1148]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:episode:51WKSvQmBqlQ6keeleJzj5","name":"GAG557: HB06 – Ada Blackjack, einsame Heldin der Arktis \u0026 Inselverzwergung im Dinosaurierland und albanische Abenteuer","artist_names":["Geschichten aus der Geschichte"],"album_name":"Geschichten aus der Geschichte","album_cover_url":"https://i.scdn.co/image/ab67656300005f1f1659266900fe987c3ee6b2ad","position":1240949,"duration":3472169,"release_date":"","track_number":0,"disc_number":0}} Jun 01 12:00:24 musikserver-matthias volumio[1148]: SPOTIFY: received: {"type":"active","data":null} Jun 01 12:00:24 musikserver-matthias volumio[1148]: info: Aligning Spotify Volume to Volumio Volume Jun 01 12:00:24 musikserver-matthias volumio[1148]: info: CoreCommandRouter::volumioGetState Jun 01 12:00:24 musikserver-matthias volumio[1148]: info: CorePlayQueue::getTrack 0 Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:00:24 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:24+02:00" level=trace msg="emitting websocket event: paused" Jun 01 12:00:24 musikserver-matthias volumio[1148]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:collection:podcasts:episodes","uri":"spotify:episode:51WKSvQmBqlQ6keeleJzj5","play_origin":"collection-podcasts-episodes"}} Jun 01 12:00:24 musikserver-matthias volumio[1148]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 12:00:24 musikserver-matthias volumio[1148]: TypeError: Cannot read properties of undefined (reading 'service') Jun 01 12:00:24 musikserver-matthias volumio[1148]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at WebSocket.emit (node:events:514:28) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver.emit (node:events:514:28) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at writeOrBuffer (node:internal/streams/writable:399:12) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at _write (node:internal/streams/writable:340:10) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Writable.write (node:internal/streams/writable:344:10) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at Socket.emit (node:events:514:28) Jun 01 12:00:24 musikserver-matthias volumio[1148]: at addChunk (node:internal/streams/readable:343:12) Jun 01 12:00:24 musikserver-matthias volumio[1148]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=debug msg="handling resume player command from 3c2169f5ba4773f98605b9ae83bd8df100829596" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=trace msg="seek to 1240949ms (diff: 628ms, samples: 54725850, bytes: 10527838)" uri="spotify:episode:51WKSvQmBqlQ6keeleJzj5" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+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 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=debug msg="resume track at 1240321ms" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=trace msg="scheduling prefetch in 2201s" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=debug msg="sending successful reply for dealer request" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:00:25 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:25+02:00" level=trace msg="emitting websocket event: playing" Jun 01 12:00:27 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:27+02:00" level=debug msg="update volume requested to 65535/65535" Jun 01 12:00:27 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:27+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 01 12:00:27 musikserver-matthias go-librespot[1623]: time="2026-06-01T12:00:27+02:00" level=trace msg="emitting websocket event: volume" Jun 01 12:00:29 musikserver-matthias sudo[1754]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 11:59' Jun 01 12:00:29 musikserver-matthias sudo[1754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"