-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Wed 2025-12-10 18:50:34 CET. -- Dec 10 18:49:52 musicbox systemd-timedated[994]: Changed local time to Wed Dec 10 18:49:52 2025 Dec 10 18:49:52 musicbox sudo[988]: pam_unix(sudo:session): session closed for user root Dec 10 18:49:52 musicbox volumio-time-update[646]: volumio-time-update-util: System time updated successfully. Dec 10 18:49:52 musicbox systemd[1]: Starting Daily apt download activities... Dec 10 18:49:52 musicbox systemd[1]: Started Volumio Time Update Utility. Dec 10 18:49:52 musicbox ntpd[768]: Listen normally on 3 wlan0 192.168.178.119:123 Dec 10 18:49:52 musicbox ntpd[768]: new interface(s) found: waking up resolver Dec 10 18:49:53 musicbox systemd[1]: Started Samba NMB Daemon. Dec 10 18:49:53 musicbox nmbd[758]: [2025/12/10 18:49:53.306391, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 10 18:49:53 musicbox nmbd[758]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Dec 10 18:49:53 musicbox systemd[1]: Starting Samba Winbind Daemon... Dec 10 18:49:53 musicbox volumio-remote-updater[631]: [2025-12-10 18:49:53] [info] asio async_connect error: system:111 (Connection refused) Dec 10 18:49:53 musicbox volumio-remote-updater[631]: [2025-12-10 18:49:53] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Dec 10 18:49:53 musicbox volumio-remote-updater[631]: [2025-12-10 18:49:53] [error] handle_connect error: Underlying Transport Error Dec 10 18:49:54 musicbox winbindd[1030]: [2025/12/10 18:49:54.383826, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Dec 10 18:49:54 musicbox winbindd[1030]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Dec 10 18:49:54 musicbox winbindd[1030]: [2025/12/10 18:49:54.486804, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 10 18:49:54 musicbox winbindd[1030]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Dec 10 18:49:54 musicbox systemd[1]: Started Samba Winbind Daemon. Dec 10 18:49:54 musicbox systemd[1]: Starting Samba SMB Daemon... Dec 10 18:49:55 musicbox smbd[1035]: [2025/12/10 18:49:55.627723, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 10 18:49:55 musicbox systemd[1]: Started Samba SMB Daemon. Dec 10 18:49:55 musicbox smbd[1035]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Dec 10 18:49:55 musicbox systemd[1]: Reached target Multi-User System. Dec 10 18:49:55 musicbox systemd[1]: Reached target Graphical Interface. Dec 10 18:49:55 musicbox systemd[1]: Starting Shutdown Raspberry Pi after 60 minutes... Dec 10 18:49:55 musicbox systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 10 18:49:55 musicbox shutdown[1042]: Shutdown scheduled for Wed 2025-12-10 19:48:55 CET, use 'shutdown -c' to cancel. Dec 10 18:49:55 musicbox systemd[1]: Started Shutdown Raspberry Pi after 60 minutes. Dec 10 18:49:55 musicbox systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 10 18:49:55 musicbox systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 10 18:49:56 musicbox systemd[1]: systemd-fsckd.service: Succeeded. Dec 10 18:49:57 musicbox systemd[1]: apt-daily.service: Succeeded. Dec 10 18:49:57 musicbox systemd[1]: Started Daily apt download activities. Dec 10 18:49:57 musicbox systemd[1]: Starting Daily apt upgrade and clean activities... Dec 10 18:49:57 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:49:57 musicbox volumio[992]: info: ----- Volumio3 ---- Dec 10 18:49:57 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:49:57 musicbox volumio[992]: info: ----- System startup ---- Dec 10 18:49:57 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:49:59 musicbox volumio[992]: info: MYVOLUMIO Environment detected Dec 10 18:50:00 musicbox volumio[992]: info: Plugin folders cleanup Dec 10 18:50:00 musicbox volumio[992]: info: Scanning into folder /volumio/app/plugins/ Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category audio_interface Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category miscellanea Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category music_service Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category plugins.json Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category system_controller Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category user_interface Dec 10 18:50:00 musicbox volumio[992]: info: Scanning into folder /data/plugins/ Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category music_service Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category system_controller Dec 10 18:50:00 musicbox volumio[992]: info: Scanning category system_hardware Dec 10 18:50:00 musicbox volumio[992]: info: Plugin folders cleanup completed Dec 10 18:50:00 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:50:00 musicbox volumio[992]: info: ----- Core plugins startup ---- Dec 10 18:50:00 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:50:00 musicbox volumio[992]: info: Loading plugins from folder /volumio/app/plugins/ Dec 10 18:50:00 musicbox volumio[992]: info: Adding plugin upnp to MyMusic Plugins Dec 10 18:50:00 musicbox volumio[992]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 10 18:50:00 musicbox volumio[992]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 10 18:50:00 musicbox volumio[992]: info: Loading plugins from folder /data/plugins/ Dec 10 18:50:00 musicbox volumio[992]: info: Loading plugin "system"... Dec 10 18:50:00 musicbox volumio[992]: info: Loading plugin "appearance"... Dec 10 18:50:00 musicbox sh[572]: timed out Dec 10 18:50:00 musicbox dhcpcd[593]: timed out Dec 10 18:50:00 musicbox sh[572]: dhcpcd exited Dec 10 18:50:00 musicbox systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Dec 10 18:50:00 musicbox dhcpcd[593]: dhcpcd exited Dec 10 18:50:00 musicbox sh[572]: ifup: failed to bring up eth0 Dec 10 18:50:00 musicbox systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Dec 10 18:50:01 musicbox systemd[1]: apt-daily-upgrade.service: Succeeded. Dec 10 18:50:01 musicbox systemd[1]: Started Daily apt upgrade and clean activities. Dec 10 18:50:01 musicbox systemd[1]: Startup finished in 15.975s (kernel) + 39.906s (userspace) = 55.882s. Dec 10 18:50:02 musicbox systemd[1]: systemd-hostnamed.service: Succeeded. Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "network"... Dec 10 18:50:03 musicbox volumio[992]: info: Refreshing Cached IP Addresses Dec 10 18:50:03 musicbox sudo[1140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 10 18:50:03 musicbox sudo[1140]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:03 musicbox volumio-remote-updater[631]: [2025-12-10 18:50:03] [connect] Successful connection Dec 10 18:50:03 musicbox sudo[1140]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:03 musicbox sudo[1142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 10 18:50:03 musicbox sudo[1142]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "services"... Dec 10 18:50:03 musicbox sudo[1142]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "alsa_controller"... Dec 10 18:50:03 musicbox sudo[1151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 10 18:50:03 musicbox sudo[1151]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:03 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "wizard"... Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "networkfs"... Dec 10 18:50:03 musicbox volumio[992]: info: Starting Udev Watcher for removable devices Dec 10 18:50:03 musicbox sudo[1168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=lukas,password=Pia0815@2612,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //se-se01/internal/music /mnt/NAS/Musik Dec 10 18:50:03 musicbox sudo[1168]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:03 musicbox volumio[992]: info: Ignoring mount for partition: boot Dec 10 18:50:03 musicbox volumio[992]: info: Ignoring mount for partition: volumio Dec 10 18:50:03 musicbox volumio[992]: info: Ignoring mount for partition: volumio_data Dec 10 18:50:03 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "volumio_command_line_client"... Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "upnp"... Dec 10 18:50:03 musicbox volumio[992]: info: [1765389003955] Starting Upmpd Daemon Dec 10 18:50:03 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "my_music"... Dec 10 18:50:03 musicbox volumio[992]: info: Loading plugin "mpd"... Dec 10 18:50:04 musicbox kernel: Key type cifs.spnego registered Dec 10 18:50:04 musicbox kernel: Key type cifs.idmap registered Dec 10 18:50:04 musicbox kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Dec 10 18:50:04 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music Dec 10 18:50:04 musicbox kernel: cryptd: max_cpu_qlen set to 1000 Dec 10 18:50:04 musicbox kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Dec 10 18:50:04 musicbox kernel: CIFS: VFS: \\se-se01 Send error in SessSetup = -13 Dec 10 18:50:04 musicbox kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Dec 10 18:50:04 musicbox sudo[1168]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:05 musicbox volumio[992]: info: Loading plugin "upnp_browser"... Dec 10 18:50:05 musicbox volumio[992]: info: Loading plugin "alarm-clock"... Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "airplay_emulation"... Dec 10 18:50:06 musicbox volumio[992]: info: Starting Shairport Sync Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "last_100"... Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "webradio"... Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "i2s_dacs"... Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "volumiodiscovery"... Dec 10 18:50:06 musicbox sudo[1151]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** For more information see Dec 10 18:50:06 musicbox node[992]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 10 18:50:06 musicbox volumio[992]: *** WARNING *** For more information see Dec 10 18:50:06 musicbox node[992]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 10 18:50:06 musicbox node[992]: *** WARNING *** For more information see Dec 10 18:50:06 musicbox node[992]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 10 18:50:06 musicbox node[992]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 10 18:50:06 musicbox node[992]: *** WARNING *** For more information see Dec 10 18:50:06 musicbox volumio[992]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 10 18:50:06 musicbox volumio[992]: info: Discovery: Started advertising with name: MusicBox Dec 10 18:50:06 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 10 18:50:06 musicbox volumio[992]: info: Loading plugin "spop"... Dec 10 18:50:09 musicbox volumio[992]: info: Loading plugin "ytcr"... Dec 10 18:50:18 musicbox volumio-remote-updater[631]: [2025-12-10 18:50:18] [connect] Successful connection Dec 10 18:50:19 musicbox volumio[992]: info: Loading plugin "autostart"... Dec 10 18:50:19 musicbox volumio[992]: info: Applying required configuration parameters for plugin autostart Dec 10 18:50:19 musicbox volumio[992]: info: AutoStart - onVolumioStart - read config.json Dec 10 18:50:19 musicbox volumio[992]: info: Loading plugin "outputs"... Dec 10 18:50:19 musicbox volumio[992]: info: Loading plugin "albumart"... Dec 10 18:50:19 musicbox volumio[992]: info: Plugin example_plugin is not enabled Dec 10 18:50:19 musicbox volumio[992]: info: Loading plugin "inputs"... Dec 10 18:50:19 musicbox volumio[992]: info: Loading plugin "updater_comm"... Dec 10 18:50:20 musicbox volumio[992]: info: Plugin mpdemulation is not enabled Dec 10 18:50:20 musicbox volumio[992]: info: Loading plugin "rest_api"... Dec 10 18:50:20 musicbox volumio[992]: info: Loading plugin "websocket"... Dec 10 18:50:20 musicbox volumio[992]: info: Starting Socket.io Server version 2.3.0 Dec 10 18:50:20 musicbox volumio[992]: info: Loading plugin "backup_restore"... Dec 10 18:50:20 musicbox volumio[992]: Forking 3 albumart workers Dec 10 18:50:20 musicbox wpa_supplicant[883]: RRM: Ignoring radio measurement request: Not RRM network Dec 10 18:50:20 musicbox volumio[992]: info: Applying required configuration parameters for plugin backup_restore Dec 10 18:50:20 musicbox volumio[992]: info: Loading plugin "rotaryencoder2"... Dec 10 18:50:21 musicbox volumio[992]: info: Loading i18n strings for locale de Dec 10 18:50:21 musicbox volumio[992]: Updating browse sources language Dec 10 18:50:21 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 18:50:22 musicbox systemd[1]: systemd-timedated.service: Succeeded. Dec 10 18:50:22 musicbox volumio[992]: Starting albumart workers Dec 10 18:50:22 musicbox volumio[992]: Starting albumart workers Dec 10 18:50:22 musicbox volumio[992]: Starting albumart workers Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::initPlayerControls Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 10 18:50:22 musicbox volumio[992]: Express server listening on port 3000 Dec 10 18:50:22 musicbox volumio[992]: [Metrics] WebUI: 26s 544.63ms Dec 10 18:50:22 musicbox volumio[992]: info: CoreStateMachine::resetVolumioState Dec 10 18:50:22 musicbox volumio[992]: info: CoreStateMachine::getcurrentVolume Dec 10 18:50:22 musicbox volumio[992]: info: CoreCommandRouter::volumioRetrievevolume Dec 10 18:50:22 musicbox sudo[1257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 10 18:50:22 musicbox sudo[1257]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:22 musicbox sudo[1257]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:22 musicbox sudo[1259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 10 18:50:22 musicbox sudo[1259]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:22 musicbox volumio[992]: info: Volumio Network Manager: Network status updated: 2 Dec 10 18:50:22 musicbox sudo[1259]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:22 musicbox volumio[992]: info: Cannot mount NAS Musik at system boot, trial number 1 ,retrying in 5 seconds Dec 10 18:50:23 musicbox volumio-remote-updater[631]: [2025-12-10 18:50:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1765389018 101 Dec 10 18:50:23 musicbox volumio[992]: 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 Dec 10 18:50:23 musicbox volumio[992]: info: VolumeController:: Volume=32 Mute =false Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::pushState Dec 10 18:50:23 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::volumioPushState Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::updateTrackBlock Dec 10 18:50:23 musicbox volumio[992]: info: CorePlayQueue::getTrackBlock Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::volumioRetrievevolume Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:23 musicbox volumio[992]: info: Executing start script for DAC IQaudIO DAC Plus Dec 10 18:50:23 musicbox volumio[992]: info: Reloading queue from file Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::setRepeat true single undefined Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::pushState Dec 10 18:50:23 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::volumioPushState Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::setRandom true Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::pushState Dec 10 18:50:23 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::volumioPushState Dec 10 18:50:23 musicbox volumio[992]: info: Setting Device type: Raspberry PI Dec 10 18:50:23 musicbox volumio[992]: info: DAC script executed Dec 10 18:50:23 musicbox avahi-daemon[648]: Host name conflict, retrying with musicbox-2 Dec 10 18:50:23 musicbox volumio[992]: info: Completed loading Core Plugins Dec 10 18:50:23 musicbox avahi-daemon[648]: Registering new address record for 192.168.178.119 on wlan0.IPv4. Dec 10 18:50:23 musicbox volumio[992]: info: Preparing to generate the ALSA configuration file Dec 10 18:50:23 musicbox volumio[992]: info: VolumeController:: Volume=32 Mute =false Dec 10 18:50:23 musicbox volumio[992]: info: CoreStateMachine::pushState Dec 10 18:50:23 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:23 musicbox volumio[992]: info: CoreCommandRouter::volumioPushState Dec 10 18:50:23 musicbox volumio[992]: info: Asound.conf file unchanged, so no further update is needed Dec 10 18:50:23 musicbox volumio[992]: info: Output device has changed, restarting MPD Dec 10 18:50:23 musicbox sudo[1313]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 10 18:50:23 musicbox sudo[1313]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:23 musicbox sudo[1316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 10 18:50:23 musicbox sudo[1316]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:24 musicbox volumio[992]: info: Output device has changed, restarting Shairport Sync Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:23 musicbox sudo[1316]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:23 musicbox sudo[1318]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 10 18:50:23 musicbox sudo[1318]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:24 musicbox systemd[1]: Started UPnP Renderer front-end to MPD. Dec 10 18:50:24 musicbox sudo[1313]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:24 musicbox volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 10 18:50:24 musicbox volumio[992]: info: ___________ START PLUGINS ___________ Dec 10 18:50:24 musicbox systemd[1]: Listening on mpd.socket. Dec 10 18:50:24 musicbox volumio[992]: info: ControllerMpd::onStart: Initializing MPD Dec 10 18:50:24 musicbox volumio[992]: info: Creating MPD Configuration file Dec 10 18:50:24 musicbox systemd[1]: Starting Music Player Daemon... Dec 10 18:50:24 musicbox sudo[1328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 10 18:50:24 musicbox sudo[1328]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 10 18:50:24 musicbox volumio[992]: info: [1765389024184] CoreMusicLibrary::Adding element Medienserver Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 18:50:24 musicbox sudo[1328]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:24 musicbox sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 10 18:50:24 musicbox sudo[1330]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:24 musicbox systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 10 18:50:24 musicbox systemd[1]: mpd.service: Succeeded. Dec 10 18:50:24 musicbox systemd[1]: Stopped Music Player Daemon. Dec 10 18:50:24 musicbox volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:24 musicbox wpa_supplicant[883]: RRM: Ignoring radio measurement request: Not RRM network Dec 10 18:50:24 musicbox systemd[1]: Starting Music Player Daemon... Dec 10 18:50:24 musicbox volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 10 18:50:24 musicbox volumio[992]: info: [1765389024434] CoreMusicLibrary::Adding element Last_100 Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 10 18:50:24 musicbox volumio[992]: info: [1765389024440] CoreMusicLibrary::Adding element Webradio Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 10 18:50:24 musicbox volumio[992]: info: Initializing BBC Radios Dec 10 18:50:24 musicbox avahi-daemon[648]: Server startup complete. Host name is musicbox-2.local. Local service cookie is 3593455020. Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:24 musicbox sudo[1336]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 10 18:50:24 musicbox sudo[1336]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:24 musicbox sudo[1336]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 10 18:50:24 musicbox sudo[1336]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:24 musicbox volumio[992]: info: Creating Spotify config file Dec 10 18:50:24 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:24 musicbox volumio[992]: info: AutoStart - onStart Dec 10 18:50:24 musicbox volumio[992]: info: [ROTARYENCODER2] loadI18nStrings: /data/plugins/system_hardware/rotaryencoder2/i18n/strings_de.json Dec 10 18:50:24 musicbox volumio[992]: info: [ROTARYENCODER2] loadI18nStrings: loaded: Dec 10 18:50:24 musicbox volumio[992]: info: [ROTARYENCODER2] onStart: Config loaded: Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] installAllOverlays: 1,2,3 Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] installAllOverlays: 1,2 Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] installAllOverlays: 1 Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] installAllOverlays: Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] installAllOverlays: end of recursion. Dec 10 18:50:25 musicbox volumio[992]: info: Volumio Calling Home Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] addOverlay for Rotary: 23 27 1 Dec 10 18:50:25 musicbox volumio[992]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 & Dec 10 18:50:25 musicbox avahi-daemon[648]: Service "MusicBox" (/services/volumio.service) successfully established. Dec 10 18:50:25 musicbox sudo[1356]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 Dec 10 18:50:25 musicbox sudo[1356]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:25 musicbox volumio[992]: info: Discovery: adding 95307504-9fd1-4df0-a09a-bb5004682349 Dec 10 18:50:25 musicbox volumio[992]: info: Discovery: Found device MusicBox Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::volumioGetState Dec 10 18:50:25 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:25 musicbox volumio[992]: info: MPD Permissions set Dec 10 18:50:25 musicbox volumio[992]: info: MPD Permissions set Dec 10 18:50:25 musicbox volumio[992]: info: Upmpdcli Daemon Started Dec 10 18:50:25 musicbox kernel: rotary-encoder rotary@17: gray Dec 10 18:50:25 musicbox kernel: input: rotary@17 as /devices/platform/rotary@17/input/input0 Dec 10 18:50:25 musicbox volumio[992]: info: Spotify config file written Dec 10 18:50:25 musicbox sudo[1356]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:25 musicbox sudo[1371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 10 18:50:25 musicbox sudo[1371]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:25 musicbox volumio[992]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 10 18:50:25 musicbox volumio[992]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 10 18:50:25 musicbox volumio[992]: info: Volumio called home Dec 10 18:50:25 musicbox volumio[992]: info: No need to fix Spotify hosts Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox systemd-udevd[1364]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 10 18:50:25 musicbox systemd[1]: Started go-librespot Daemon. Dec 10 18:50:25 musicbox go-librespot[1374]: go-librespot daemon starting... Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 18:50:25 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 18:50:25 musicbox sudo[1371]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:26 musicbox volumio[992]: info: Discovery: A device disappeared from network Dec 10 18:50:26 musicbox volumio[992]: info: Discovery: Device musicbox disappeared from network Dec 10 18:50:26 musicbox go-librespot[1374]: time="2025-12-10T18:50:26+01:00" level=info msg="running go-librespot 0.4.0" Dec 10 18:50:26 musicbox go-librespot[1374]: time="2025-12-10T18:50:26+01:00" level=debug msg="app state loaded" Dec 10 18:50:26 musicbox volumio[992]: info: /dev/input: Dec 10 18:50:26 musicbox volumio[992]: by-path Dec 10 18:50:26 musicbox volumio[992]: event0 Dec 10 18:50:26 musicbox volumio[992]: mice Dec 10 18:50:26 musicbox volumio[992]: /dev/input/by-path: Dec 10 18:50:26 musicbox volumio[992]: platform-rotary@17-event Dec 10 18:50:26 musicbox go-librespot[1374]: time="2025-12-10T18:50:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 10 18:50:26 musicbox volumio[992]: info: Starting Shairport Sync Dec 10 18:50:26 musicbox volumio[992]: info: Starting Shairport Sync Dec 10 18:50:26 musicbox volumio[992]: info: Starting Shairport Sync Dec 10 18:50:26 musicbox sudo[1393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 10 18:50:26 musicbox sudo[1393]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:26 musicbox sudo[1395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 10 18:50:26 musicbox sudo[1395]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:26 musicbox volumio[992]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 18:50:26 musicbox volumio[992]: SPOTIFY: BQBYEf_0prgB3DIuiG19FV51XaMMEl0AL4U7X3CysvCrmhS5iIgy4jrQTsjVWouiVT8tUhxi9gUD4ajUQ4Ki5-XNbfBrR_YokL8_MwILb98OdYKP4qNyeqXniqk0k-9MpUTejQApnMKzHnAWliG71b_wvZezgLC0DSNFfLYHdbwhOh7vMvi_XHu4t6kemXISQSFqqm16Cb6xgHFT10DIXoZU-3nlbEJzOwhn5jkftbt4VA2tqwUACbAQIWJnZxMpLBuBMUBbslUom7mkyn7L-BBHrTnRiAGh6M91YRji_Ming3RuuI8Xb6BE_ZC7 Dec 10 18:50:26 musicbox volumio[992]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 18:50:26 musicbox systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 10 18:50:26 musicbox volumio[992]: info: New Spotify access token = BQBYEf_0prgB3DIuiG19FV51XaMMEl0AL4U7X3CysvCrmhS5iIgy4jrQTsjVWouiVT8tUhxi9gUD4ajUQ4Ki5-XNbfBrR_YokL8_MwILb98OdYKP4qNyeqXniqk0k-9MpUTejQApnMKzHnAWliG71b_wvZezgLC0DSNFfLYHdbwhOh7vMvi_XHu4t6kemXISQSFqqm16Cb6xgHFT10DIXoZU-3nlbEJzOwhn5jkftbt4VA2tqwUACbAQIWJnZxMpLBuBMUBbslUom7mkyn7L-BBHrTnRiAGh6M91YRji_Ming3RuuI8Xb6BE_ZC7 Dec 10 18:50:26 musicbox volumio[992]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 10 18:50:26 musicbox sudo[1398]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 10 18:50:26 musicbox sudo[1398]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:26 musicbox systemd[1]: shairport-sync.service: Succeeded. Dec 10 18:50:26 musicbox systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 10 18:50:26 musicbox volumio[992]: info: CoreCommandRouter::volumioGetState Dec 10 18:50:26 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:26 musicbox volumio[992]: info: CoreCommandRouter::volumioGetState Dec 10 18:50:26 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:27 musicbox systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 10 18:50:27 musicbox sudo[1393]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:27 musicbox sudo[1398]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:27 musicbox sudo[1395]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:27 musicbox volumio[992]: info: Shairport-Sync Started Dec 10 18:50:27 musicbox volumio[992]: Error adding Membership: Error: addMembership EINVAL Dec 10 18:50:27 musicbox volumio[992]: info: Shairport-Sync Started Dec 10 18:50:27 musicbox volumio[992]: info: Shairport-Sync Started Dec 10 18:50:27 musicbox volumio[992]: info: Discovery: adding 95307504-9fd1-4df0-a09a-bb5004682349 Dec 10 18:50:27 musicbox volumio[992]: info: Discovery: Found device MusicBox Dec 10 18:50:27 musicbox volumio[992]: info: CoreCommandRouter::volumioGetState Dec 10 18:50:27 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:27 musicbox volumio[992]: SPOTIFY: User informations: {"country":"IN","display_name":"Lukas Trausch","email":"management@gipfelnovation.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31bjkbz74djgmahibcw3dkhb6sha"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31bjkbz74djgmahibcw3dkhb6sha","id":"31bjkbz74djgmahibcw3dkhb6sha","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85c78e14e5de121b3a5a19cc70","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82c78e14e5de121b3a5a19cc70","width":64}],"product":"premium","type":"user","uri":"spotify:user:31bjkbz74djgmahibcw3dkhb6sha"} Dec 10 18:50:27 musicbox volumio[992]: info: Spotify Successfully logged in Dec 10 18:50:27 musicbox volumio[992]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 10 18:50:27 musicbox volumio[992]: info: [1765389027448] CoreMusicLibrary::Adding element Spotify Dec 10 18:50:27 musicbox volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 18:50:27 musicbox volumio[992]: Cannot find translation for source Spotify Dec 10 18:50:27 musicbox volumio[992]: info: [ROTARYENCODER2] addOverlay for Button: 4 true up Dec 10 18:50:27 musicbox volumio[992]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 & Dec 10 18:50:27 musicbox sudo[1408]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 10 18:50:27 musicbox sudo[1408]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=info msg="zeroconf server listening on port 35833" Dec 10 18:50:27 musicbox sudo[1408]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:27 musicbox kernel: input: button@4 as /devices/platform/button@4/input/input1 Dec 10 18:50:27 musicbox volumio[992]: info: /dev/input: Dec 10 18:50:27 musicbox volumio[992]: by-path Dec 10 18:50:27 musicbox volumio[992]: event0 Dec 10 18:50:27 musicbox volumio[992]: event1 Dec 10 18:50:27 musicbox volumio[992]: mice Dec 10 18:50:27 musicbox volumio[992]: /dev/input/by-path: Dec 10 18:50:27 musicbox volumio[992]: platform-rotary@17-event Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="obtained new client token: AACusewxzgxwo+9teA78yte75xMCweJ2r92BkXfimXxRdmYtZkMQDeDomMFPFliPbGctyYkgf8nLtYY1WMWIdCK/EQ3c1clVFA3lVl+/jWZ4Jhd5wIh/WornIBv5aimXKsypINKgfY7AJlhXorhG9usBnhxrUeFHgcIK/nWwMztMHF831eMZJsCt2ut5eFOBB5NnUMmTcwx9DizTEUg8uW278GgJFM+fIohWdlbrslBIGFnaEWW1dg==" Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 10 18:50:27 musicbox systemd-udevd[1364]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="completed keyexchange" Dec 10 18:50:27 musicbox go-librespot[1374]: time="2025-12-10T18:50:27+01:00" level=debug msg="completed challenge" Dec 10 18:50:28 musicbox sudo[1421]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=lukas,password=Pia0815@2612,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //se-se01/internal/music /mnt/NAS/Musik Dec 10 18:50:28 musicbox sudo[1421]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=info msg="authenticated AP" username="31************************ha" Dec 10 18:50:28 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=info msg="authenticated Login5" username="31************************ha" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="initializing zeroconf session" username="31************************ha" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="dealer connection opened" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=trace msg="starting accesspoint recv loop" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=trace msg="starting dealer recv loop" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=trace msg="received accesspoint ping" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="received connection id: NGRkYjMzMTktYThh...MzY2MjNBMEQ5NA==" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 10 18:50:28 musicbox volumio[992]: info: [yt-cast-receiver] DIAL server listening on port 8098 Dec 10 18:50:28 musicbox volumio[992]: info: CoreCommandRouter::volumioRetrievevolume Dec 10 18:50:28 musicbox volumio[992]: info: VolumeController:: Volume=32 Mute =false Dec 10 18:50:28 musicbox volumio[992]: info: CoreCommandRouter::volumioGetState Dec 10 18:50:28 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:28 musicbox volumio[992]: info: CoreStateMachine::pushState Dec 10 18:50:28 musicbox volumio[992]: info: CorePlayQueue::getTrack 0 Dec 10 18:50:28 musicbox volumio[992]: info: CoreCommandRouter::volumioPushState Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 10 18:50:28 musicbox go-librespot[1374]: time="2025-12-10T18:50:28+01:00" level=trace msg="received accesspoint pong ack" Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: 1,2,3 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: 1,2 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: 1 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: end of recursion. Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: rotary Dec 10 18:50:28 musicbox sudo[1429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 10 18:50:28 musicbox sudo[1429]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:28 musicbox sudo[1429]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=23pinB=27 in Overlays (in load order): Dec 10 18:50:28 musicbox volumio[992]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 Dec 10 18:50:28 musicbox volumio[992]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: rotary 1 uses overlay 0 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: attach rotary 1 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-rotary@17-event, type: rotary Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: button Dec 10 18:50:28 musicbox sudo[1433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Dec 10 18:50:28 musicbox sudo[1433]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 10 18:50:28 musicbox sudo[1433]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=4pinB=undefined in Overlays (in load order): Dec 10 18:50:28 musicbox volumio[992]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 Dec 10 18:50:28 musicbox volumio[992]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] checkOverlayExists: button 1 uses overlay 1 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners: attach button 1 Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-button@4-event, type: button Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners rotaries: Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners buttons: Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners rotaries: Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] attachAllListeners buttons: Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] onStart: Attach Event-handles now. Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] Now addAllEventHandles for rotaries. Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: rotary Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] Now addAllEventHandles for buttons. Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: button Dec 10 18:50:28 musicbox volumio[992]: info: [ROTARYENCODER2] addEventHandle: adding handle : Dec 10 18:50:29 musicbox volumio[992]: info: [ROTARYENCODER2] onStart: Plugin successfully started. Dec 10 18:50:29 musicbox volumio[992]: info: go-librespot daemon successfully initialized Dec 10 18:50:30 musicbox mpd[1351]: Dec 10 18:50 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 10 18:50:30 musicbox systemd[1]: Started Music Player Daemon. Dec 10 18:50:30 musicbox sudo[1330]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:30 musicbox volumio[992]: Upnp client error: Error: This socket has been ended by the other party Dec 10 18:50:30 musicbox volumio[992]: Upnp client error: Error: This socket has been ended by the other party Dec 10 18:50:30 musicbox sudo[1318]: pam_unix(sudo:session): session closed for user root Dec 10 18:50:30 musicbox go-librespot[1374]: time="2025-12-10T18:50:30+01:00" level=debug msg="handling transfer player command from 106d9f9963a0285e607bdbe4031ad345a3c08ef0" Dec 10 18:50:30 musicbox go-librespot[1374]: time="2025-12-10T18:50:30+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:65WNH6UVyWwp1IfJeRaYy7" Dec 10 18:50:30 musicbox go-librespot[1374]: time="2025-12-10T18:50:30+01:00" level=trace msg="fetched new page 0 with 29 items (list: 29)" uri="spotify:playlist:65WNH6UVyWwp1IfJeRaYy7" Dec 10 18:50:30 musicbox go-librespot[1374]: time="2025-12-10T18:50:30+01:00" level=debug msg="shuffled context with seed 5117944572886460819 (len: 29, keep: 5)" uri="spotify:playlist:65WNH6UVyWwp1IfJeRaYy7" Dec 10 18:50:30 musicbox go-librespot[1374]: time="2025-12-10T18:50:30+01:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=trace msg="emitting websocket event: will_play" Dec 10 18:50:31 musicbox volumio[992]: error: MPD error: The expression evaluated to a falsy value: Dec 10 18:50:31 musicbox volumio[992]: assert.ok(self.idling) Dec 10 18:50:31 musicbox volumio[992]: error: The expression evaluated to a falsy value: Dec 10 18:50:31 musicbox volumio[992]: assert.ok(self.idling) Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="selected format OGG_VORBIS_160 (29b136a966a8c47005ebd56a5db74f041ce8f21b)" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="requested aes key for file 29b136a966a8c47005ebd56a5db74f041ce8f21b, gid: 7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Dec 10 18:50:31 musicbox volumio[992]: info: MPD running with PID1351 Dec 10 18:50:31 musicbox volumio[992]: ,establishing connection Dec 10 18:50:31 musicbox volumio[992]: error: updateQueue error: null Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox volumio[992]: info: Completed starting Core Plugins Dec 10 18:50:31 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:50:31 musicbox volumio[992]: info: ----- MyVolumio plugins startup ---- Dec 10 18:50:31 musicbox volumio[992]: info: ------------------------------------------- Dec 10 18:50:31 musicbox volumio[992]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 10 18:50:31 musicbox volumio[992]: error: updateQueue error: null Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="fetched first chunk of 6, total size is 3029931 bytes" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="created new output device" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=info msg="loaded track \"Faint\" (paused: true, position: 0ms, duration: 162106ms, prefetched: false)" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=trace msg="emitting websocket event: metadata" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=trace msg="emitting websocket event: active" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="sending successful reply for dealer request" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="fetched chunk 2/5, size: 524288" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=trace msg="emitting websocket event: paused" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="fetched chunk 1/5, size: 524288" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:31 musicbox go-librespot[1374]: time="2025-12-10T18:50:31+01:00" level=debug msg="fetched chunk 3/5, size: 524288" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:32 musicbox volumio[992]: info: Initializing connection to go-librespot Websocket Dec 10 18:50:32 musicbox go-librespot[1374]: time="2025-12-10T18:50:32+01:00" level=debug msg="new websocket client" Dec 10 18:50:32 musicbox volumio[992]: info: Connection to go-librespot Websocket established Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="handling resume player command from 106d9f9963a0285e607bdbe4031ad345a3c08ef0" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=trace msg="seek to 0ms (diff: -132ms, samples: 0, bytes: 0)" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="resume track at 132ms" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:7AB0cUXnzuSlAnyHOqmrZr" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=trace msg="scheduling prefetch in 132s" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="sending successful reply for dealer request" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 10 18:50:33 musicbox go-librespot[1374]: time="2025-12-10T18:50:33+01:00" level=trace msg="emitting websocket event: playing" Dec 10 18:50:33 musicbox volumio[992]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:65WNH6UVyWwp1IfJeRaYy7","uri":"spotify:track:7AB0cUXnzuSlAnyHOqmrZr","resume":true,"play_origin":"playlist"}} Dec 10 18:50:33 musicbox volumio[992]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 10 18:50:33 musicbox volumio[992]: TypeError: Cannot read property 'service' of undefined Dec 10 18:50:33 musicbox volumio[992]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 10 18:50:33 musicbox volumio[992]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 10 18:50:33 musicbox volumio[992]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 10 18:50:33 musicbox volumio[992]: at WebSocket.emit (events.js:315:20) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.emit (events.js:315:20) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 10 18:50:33 musicbox volumio[992]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 10 18:50:33 musicbox volumio[992]: at writeOrBuffer (internal/streams/writable.js:358:12) Dec 10 18:50:33 musicbox volumio[992]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Dec 10 18:50:33 musicbox volumio[992]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 10 18:50:33 musicbox volumio[992]: at Socket.emit (events.js:315:20) Dec 10 18:50:33 musicbox volumio[992]: at addChunk (internal/streams/readable.js:309:12) Dec 10 18:50:33 musicbox volumio[992]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 10 18:50:33 musicbox volumio[992]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 10 18:50:34 musicbox sudo[1498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-10 18:49 Dec 10 18:50:34 musicbox sudo[1498]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"