-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Fri 2025-05-16 23:46:32 CEST. -- May 16 23:45:50 musicbox systemd-timedated[1022]: Changed local time to Fri May 16 23:45:50 2025 May 16 23:45:50 musicbox sudo[1020]: pam_unix(sudo:session): session closed for user root May 16 23:45:50 musicbox volumio-time-update[618]: volumio-time-update-util: System time updated successfully. May 16 23:45:50 musicbox systemd[1]: Starting Daily apt download activities... May 16 23:45:50 musicbox systemd[1]: Started Volumio Time Update Utility. May 16 23:45:50 musicbox ntpd[767]: Listen normally on 3 wlan0 192.168.178.119:123 May 16 23:45:50 musicbox ntpd[767]: new interface(s) found: waking up resolver May 16 23:45:51 musicbox volumio-remote-updater[622]: [2025-05-16 23:45:51] [info] asio async_connect error: system:111 (Connection refused) May 16 23:45:51 musicbox volumio-remote-updater[622]: [2025-05-16 23:45:51] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 16 23:45:51 musicbox volumio-remote-updater[622]: [2025-05-16 23:45:51] [error] handle_connect error: Underlying Transport Error May 16 23:45:52 musicbox nmbd[762]: [2025/05/16 23:45:52.024419, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 16 23:45:52 musicbox systemd[1]: Started Samba NMB Daemon. May 16 23:45:52 musicbox nmbd[762]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 16 23:45:52 musicbox systemd[1]: Starting Samba Winbind Daemon... May 16 23:45:52 musicbox winbindd[1043]: [2025/05/16 23:45:52.985241, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 16 23:45:52 musicbox winbindd[1043]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 16 23:45:53 musicbox winbindd[1043]: [2025/05/16 23:45:53.016150, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 16 23:45:53 musicbox systemd[1]: Started Samba Winbind Daemon. May 16 23:45:53 musicbox winbindd[1043]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 16 23:45:53 musicbox systemd[1]: Starting Samba SMB Daemon... May 16 23:45:54 musicbox systemd[1]: Started Samba SMB Daemon. May 16 23:45:54 musicbox systemd[1]: Reached target Multi-User System. May 16 23:45:54 musicbox smbd[1048]: [2025/05/16 23:45:54.067166, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 16 23:45:54 musicbox smbd[1048]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 16 23:45:54 musicbox systemd[1]: Reached target Graphical Interface. May 16 23:45:54 musicbox systemd[1]: Starting Update UTMP about System Runlevel Changes... May 16 23:45:54 musicbox systemd[1]: Starting Shutdown Raspberry Pi after 60 minutes... May 16 23:45:54 musicbox systemd[1]: systemd-fsckd.service: Succeeded. May 16 23:45:54 musicbox shutdown[1057]: Shutdown scheduled for Sat 2025-05-17 00:44:54 CEST, use 'shutdown -c' to cancel. May 16 23:45:54 musicbox systemd[1]: Started Shutdown Raspberry Pi after 60 minutes. May 16 23:45:54 musicbox systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 16 23:45:54 musicbox systemd[1]: Started Update UTMP about System Runlevel Changes. May 16 23:45:55 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:45:55 musicbox volumio[1002]: info: ----- Volumio3 ---- May 16 23:45:55 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:45:55 musicbox volumio[1002]: info: ----- System startup ---- May 16 23:45:55 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:45:55 musicbox systemd[1]: apt-daily.service: Succeeded. May 16 23:45:55 musicbox systemd[1]: Started Daily apt download activities. May 16 23:45:55 musicbox systemd[1]: Starting Daily apt upgrade and clean activities... May 16 23:45:57 musicbox avahi-daemon[600]: Host name conflict, retrying with musicbox-2 May 16 23:45:57 musicbox avahi-daemon[600]: Registering new address record for 192.168.178.119 on wlan0.IPv4. May 16 23:45:57 musicbox volumio[1002]: info: MYVOLUMIO Environment detected May 16 23:45:57 musicbox volumio[1002]: info: Plugin folders cleanup May 16 23:45:57 musicbox volumio[1002]: info: Scanning into folder /volumio/app/plugins/ May 16 23:45:57 musicbox volumio[1002]: info: Scanning category audio_interface May 16 23:45:57 musicbox volumio[1002]: info: Scanning category miscellanea May 16 23:45:57 musicbox volumio[1002]: info: Scanning category music_service May 16 23:45:57 musicbox volumio[1002]: info: Scanning category plugins.json May 16 23:45:57 musicbox volumio[1002]: info: Scanning category system_controller May 16 23:45:57 musicbox volumio[1002]: info: Scanning category user_interface May 16 23:45:57 musicbox volumio[1002]: info: Scanning into folder /data/plugins/ May 16 23:45:57 musicbox volumio[1002]: info: Scanning category music_service May 16 23:45:57 musicbox volumio[1002]: info: Scanning category system_controller May 16 23:45:57 musicbox volumio[1002]: info: Scanning category system_hardware May 16 23:45:57 musicbox volumio[1002]: info: Plugin folders cleanup completed May 16 23:45:57 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:45:57 musicbox volumio[1002]: info: ----- Core plugins startup ---- May 16 23:45:57 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:45:57 musicbox volumio[1002]: info: Loading plugins from folder /volumio/app/plugins/ May 16 23:45:57 musicbox volumio[1002]: info: Adding plugin upnp to MyMusic Plugins May 16 23:45:57 musicbox volumio[1002]: info: Adding plugin airplay_emulation to MyMusic Plugins May 16 23:45:57 musicbox volumio[1002]: info: Adding plugin upnp_browser to MyMusic Plugins May 16 23:45:57 musicbox volumio[1002]: info: Loading plugins from folder /data/plugins/ May 16 23:45:57 musicbox volumio[1002]: info: Loading plugin "system"... May 16 23:45:57 musicbox volumio[1002]: info: Loading plugin "appearance"... May 16 23:45:58 musicbox sh[571]: timed out May 16 23:45:58 musicbox dhcpcd[590]: timed out May 16 23:45:58 musicbox sh[571]: dhcpcd exited May 16 23:45:58 musicbox dhcpcd[590]: dhcpcd exited May 16 23:45:58 musicbox sh[571]: ifup: failed to bring up eth0 May 16 23:45:58 musicbox systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 16 23:45:58 musicbox systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 16 23:45:58 musicbox avahi-daemon[600]: Server startup complete. Host name is musicbox-2.local. Local service cookie is 1445588804. May 16 23:45:58 musicbox systemd[1]: apt-daily-upgrade.service: Succeeded. May 16 23:45:58 musicbox systemd[1]: Started Daily apt upgrade and clean activities. May 16 23:45:58 musicbox systemd[1]: Startup finished in 16.712s (kernel) + 40.317s (userspace) = 57.030s. May 16 23:45:59 musicbox avahi-daemon[600]: Service "MusicBox" (/services/volumio.service) successfully established. May 16 23:46:00 musicbox volumio[1002]: info: Loading plugin "network"... May 16 23:46:00 musicbox volumio[1002]: info: Refreshing Cached IP Addresses May 16 23:46:00 musicbox sudo[1153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 16 23:46:00 musicbox sudo[1153]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:00 musicbox sudo[1153]: pam_unix(sudo:session): session closed for user root May 16 23:46:00 musicbox sudo[1155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 16 23:46:00 musicbox sudo[1155]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:00 musicbox sudo[1155]: pam_unix(sudo:session): session closed for user root May 16 23:46:00 musicbox volumio[1002]: info: Loading plugin "services"... May 16 23:46:00 musicbox volumio[1002]: info: Loading plugin "alsa_controller"... May 16 23:46:00 musicbox sudo[1164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 16 23:46:00 musicbox sudo[1164]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:01 musicbox systemd[1]: systemd-hostnamed.service: Succeeded. May 16 23:46:01 musicbox volumio-remote-updater[622]: [2025-05-16 23:46:01] [connect] Successful connection May 16 23:46:01 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "wizard"... May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "networkfs"... May 16 23:46:01 musicbox volumio[1002]: info: Starting Udev Watcher for removable devices May 16 23:46:01 musicbox sudo[1184]: 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 May 16 23:46:01 musicbox sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:01 musicbox volumio[1002]: info: Ignoring mount for partition: boot May 16 23:46:01 musicbox volumio[1002]: info: Ignoring mount for partition: volumio May 16 23:46:01 musicbox volumio[1002]: info: Ignoring mount for partition: volumio_data May 16 23:46:01 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "volumio_command_line_client"... May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "upnp"... May 16 23:46:01 musicbox volumio[1002]: info: [1747431961493] Starting Upmpd Daemon May 16 23:46:01 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "my_music"... May 16 23:46:01 musicbox volumio[1002]: info: Loading plugin "mpd"... May 16 23:46:01 musicbox kernel: Key type cifs.spnego registered May 16 23:46:01 musicbox kernel: Key type cifs.idmap registered May 16 23:46:01 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. May 16 23:46:01 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music May 16 23:46:02 musicbox kernel: cryptd: max_cpu_qlen set to 1000 May 16 23:46:02 musicbox sudo[1184]: pam_unix(sudo:session): session closed for user root May 16 23:46:02 musicbox kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE May 16 23:46:02 musicbox kernel: CIFS: VFS: \\se-se01 Send error in SessSetup = -13 May 16 23:46:02 musicbox kernel: CIFS: VFS: cifs_mount failed w/return code = -13 May 16 23:46:02 musicbox volumio[1002]: info: Loading plugin "upnp_browser"... May 16 23:46:03 musicbox volumio[1002]: info: Loading plugin "alarm-clock"... May 16 23:46:03 musicbox volumio[1002]: info: Loading plugin "airplay_emulation"... May 16 23:46:03 musicbox volumio[1002]: info: Starting Shairport Sync May 16 23:46:03 musicbox volumio[1002]: info: Loading plugin "last_100"... May 16 23:46:03 musicbox volumio[1002]: info: Loading plugin "webradio"... May 16 23:46:04 musicbox volumio[1002]: info: Loading plugin "i2s_dacs"... May 16 23:46:04 musicbox sudo[1164]: pam_unix(sudo:session): session closed for user root May 16 23:46:04 musicbox volumio[1002]: info: Loading plugin "volumiodiscovery"... May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** Please fix your application to use the native API of Avahi! May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** For more information see May 16 23:46:04 musicbox node[1002]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** Please fix your application to use the native API of Avahi! May 16 23:46:04 musicbox volumio[1002]: *** WARNING *** For more information see May 16 23:46:04 musicbox node[1002]: *** WARNING *** Please fix your application to use the native API of Avahi! May 16 23:46:04 musicbox node[1002]: *** WARNING *** For more information see May 16 23:46:04 musicbox node[1002]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 16 23:46:04 musicbox node[1002]: *** WARNING *** Please fix your application to use the native API of Avahi! May 16 23:46:04 musicbox node[1002]: *** WARNING *** For more information see May 16 23:46:04 musicbox volumio[1002]: info: Applying required configuration parameters for plugin volumiodiscovery May 16 23:46:04 musicbox volumio[1002]: info: Discovery: Started advertising with name: MusicBox May 16 23:46:04 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 16 23:46:04 musicbox volumio[1002]: info: Loading plugin "spop"... May 16 23:46:07 musicbox volumio[1002]: info: Loading plugin "ytcr"... May 16 23:46:16 musicbox volumio-remote-updater[622]: [2025-05-16 23:46:16] [connect] Successful connection May 16 23:46:16 musicbox volumio[1002]: info: Loading plugin "autostart"... May 16 23:46:17 musicbox volumio[1002]: info: Applying required configuration parameters for plugin autostart May 16 23:46:17 musicbox volumio[1002]: info: AutoStart - onVolumioStart - read config.json May 16 23:46:17 musicbox volumio[1002]: info: Loading plugin "outputs"... May 16 23:46:17 musicbox volumio[1002]: info: Loading plugin "albumart"... May 16 23:46:17 musicbox volumio[1002]: info: Plugin example_plugin is not enabled May 16 23:46:17 musicbox volumio[1002]: info: Loading plugin "inputs"... May 16 23:46:17 musicbox volumio[1002]: info: Loading plugin "updater_comm"... May 16 23:46:17 musicbox volumio[1002]: info: Plugin mpdemulation is not enabled May 16 23:46:17 musicbox volumio[1002]: info: Loading plugin "rest_api"... May 16 23:46:18 musicbox volumio[1002]: info: Loading plugin "websocket"... May 16 23:46:18 musicbox volumio[1002]: info: Starting Socket.io Server version 2.3.0 May 16 23:46:18 musicbox volumio[1002]: info: Loading plugin "backup_restore"... May 16 23:46:18 musicbox volumio[1002]: Forking 3 albumart workers May 16 23:46:18 musicbox volumio[1002]: info: Applying required configuration parameters for plugin backup_restore May 16 23:46:18 musicbox volumio[1002]: info: Loading plugin "rotaryencoder2"... May 16 23:46:19 musicbox volumio[1002]: info: Loading i18n strings for locale de May 16 23:46:19 musicbox volumio[1002]: Updating browse sources language May 16 23:46:19 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 16 23:46:20 musicbox volumio[1002]: Starting albumart workers May 16 23:46:20 musicbox volumio[1002]: Starting albumart workers May 16 23:46:20 musicbox systemd[1]: systemd-timedated.service: Succeeded. May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::initPlayerControls May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 16 23:46:20 musicbox volumio[1002]: Starting albumart workers May 16 23:46:20 musicbox volumio[1002]: Express server listening on port 3000 May 16 23:46:20 musicbox volumio[1002]: [Metrics] WebUI: 26s 913.12ms May 16 23:46:20 musicbox volumio[1002]: info: CoreStateMachine::resetVolumioState May 16 23:46:20 musicbox volumio[1002]: info: CoreStateMachine::getcurrentVolume May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::volumioRetrievevolume May 16 23:46:20 musicbox sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 16 23:46:20 musicbox sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:20 musicbox sudo[1274]: pam_unix(sudo:session): session closed for user root May 16 23:46:20 musicbox sudo[1276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 16 23:46:20 musicbox volumio[1002]: info: Volumio Network Manager: Network status updated: 2 May 16 23:46:20 musicbox sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:20 musicbox sudo[1276]: pam_unix(sudo:session): session closed for user root May 16 23:46:20 musicbox volumio[1002]: info: Cannot mount NAS Musik at system boot, trial number 1 ,retrying in 5 seconds May 16 23:46:20 musicbox volumio-remote-updater[622]: [2025-05-16 23:46:20] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1747431976 101 May 16 23:46:20 musicbox volumio[1002]: 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 May 16 23:46:20 musicbox volumio[1002]: info: VolumeController:: Volume=30 Mute =false May 16 23:46:20 musicbox volumio[1002]: info: CoreStateMachine::pushState May 16 23:46:20 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::volumioPushState May 16 23:46:20 musicbox volumio[1002]: info: CoreStateMachine::updateTrackBlock May 16 23:46:20 musicbox volumio[1002]: info: CorePlayQueue::getTrackBlock May 16 23:46:20 musicbox volumio[1002]: info: CoreCommandRouter::volumioRetrievevolume May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:21 musicbox volumio[1002]: info: Executing start script for DAC IQaudIO DAC Plus May 16 23:46:21 musicbox volumio[1002]: info: Reloading queue from file May 16 23:46:21 musicbox volumio[1002]: info: Setting Device type: Raspberry PI May 16 23:46:21 musicbox volumio[1002]: info: CoreStateMachine::setRepeat true single undefined May 16 23:46:21 musicbox volumio[1002]: info: CoreStateMachine::pushState May 16 23:46:21 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::volumioPushState May 16 23:46:21 musicbox volumio[1002]: info: CoreStateMachine::setRandom true May 16 23:46:21 musicbox volumio[1002]: info: CoreStateMachine::pushState May 16 23:46:21 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::volumioPushState May 16 23:46:21 musicbox volumio[1002]: info: VolumeController:: Volume=30 Mute =false May 16 23:46:21 musicbox volumio[1002]: info: CoreStateMachine::pushState May 16 23:46:21 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::volumioPushState May 16 23:46:21 musicbox volumio[1002]: info: DAC script executed May 16 23:46:21 musicbox volumio[1002]: info: Completed loading Core Plugins May 16 23:46:21 musicbox volumio[1002]: info: Preparing to generate the ALSA configuration file May 16 23:46:21 musicbox volumio[1002]: info: Asound.conf file unchanged, so no further update is needed May 16 23:46:21 musicbox volumio[1002]: info: Output device has changed, restarting MPD May 16 23:46:21 musicbox sudo[1322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 16 23:46:21 musicbox sudo[1322]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:21 musicbox sudo[1325]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 16 23:46:21 musicbox sudo[1325]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:21 musicbox systemd[1]: Started UPnP Renderer front-end to MPD. May 16 23:46:21 musicbox volumio[1002]: info: Output device has changed, restarting Shairport Sync May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:21 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:21 musicbox sudo[1325]: pam_unix(sudo:session): session closed for user root May 16 23:46:21 musicbox sudo[1322]: pam_unix(sudo:session): session closed for user root May 16 23:46:21 musicbox sudo[1328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 16 23:46:21 musicbox sudo[1328]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:22 musicbox systemd[1]: Stopping Music Player Daemon... May 16 23:46:22 musicbox volumio[1002]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 16 23:46:22 musicbox volumio[1002]: info: ___________ START PLUGINS ___________ May 16 23:46:22 musicbox volumio[1002]: info: ControllerMpd::onStart: Initializing MPD May 16 23:46:22 musicbox volumio[1002]: info: Creating MPD Configuration file May 16 23:46:22 musicbox sudo[1343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 16 23:46:22 musicbox sudo[1343]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:22 musicbox volumio[1002]: info: [1747431982151] CoreMusicLibrary::Adding element Medienserver May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 16 23:46:22 musicbox sudo[1343]: pam_unix(sudo:session): session closed for user root May 16 23:46:22 musicbox sudo[1345]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 16 23:46:22 musicbox sudo[1345]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:22 musicbox systemd[1]: mpd.service: Succeeded. May 16 23:46:22 musicbox systemd[1]: Stopped Music Player Daemon. May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:22 musicbox systemd[1]: Starting Music Player Daemon... May 16 23:46:22 musicbox volumio[1002]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:22 musicbox volumio[1002]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 16 23:46:22 musicbox volumio[1002]: info: [1747431982514] CoreMusicLibrary::Adding element Last_100 May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 16 23:46:22 musicbox volumio[1002]: info: [1747431982520] CoreMusicLibrary::Adding element Webradio May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 16 23:46:22 musicbox volumio[1002]: info: Initializing BBC Radios May 16 23:46:22 musicbox sudo[1348]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 16 23:46:22 musicbox sudo[1348]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:22 musicbox sudo[1348]: pam_unix(sudo:session): session closed for user root May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:22 musicbox volumio[1002]: info: Creating Spotify config file May 16 23:46:22 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: AutoStart - onStart May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] loadI18nStrings: /data/plugins/system_hardware/rotaryencoder2/i18n/strings_de.json May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] loadI18nStrings: loaded: May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] onStart: Config loaded: May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] installAllOverlays: 1,2,3 May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] installAllOverlays: 1,2 May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] installAllOverlays: 1 May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] installAllOverlays: May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] installAllOverlays: end of recursion. May 16 23:46:23 musicbox volumio[1002]: info: Volumio Calling Home May 16 23:46:23 musicbox volumio[1002]: info: [ROTARYENCODER2] addOverlay for Rotary: 23 27 1 May 16 23:46:23 musicbox volumio[1002]: 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 & May 16 23:46:23 musicbox sudo[1371]: 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 May 16 23:46:23 musicbox sudo[1371]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:23 musicbox sudo[1371]: pam_unix(sudo:session): session closed for user root May 16 23:46:23 musicbox kernel: rotary-encoder rotary@17: gray May 16 23:46:23 musicbox kernel: input: rotary@17 as /devices/platform/rotary@17/input/input0 May 16 23:46:23 musicbox volumio[1002]: info: Discovery: adding 95307504-9fd1-4df0-a09a-bb5004682349 May 16 23:46:23 musicbox volumio[1002]: info: Discovery: Found device MusicBox May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::volumioGetState May 16 23:46:23 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:23 musicbox volumio[1002]: info: MPD Permissions set May 16 23:46:23 musicbox volumio[1002]: info: MPD Permissions set May 16 23:46:23 musicbox volumio[1002]: info: Upmpdcli Daemon Started May 16 23:46:23 musicbox volumio[1002]: info: Volumio called home May 16 23:46:23 musicbox volumio[1002]: info: Spotify config file written May 16 23:46:23 musicbox sudo[1389]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 16 23:46:23 musicbox sudo[1389]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:23 musicbox volumio[1002]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 16 23:46:23 musicbox volumio[1002]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 May 16 23:46:23 musicbox volumio[1002]: info: /dev/input: May 16 23:46:23 musicbox volumio[1002]: event0 May 16 23:46:23 musicbox volumio[1002]: mice May 16 23:46:23 musicbox systemd-udevd[1383]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox systemd[1]: Started go-librespot Daemon. May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox go-librespot[1391]: go-librespot daemon starting... May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox sudo[1389]: pam_unix(sudo:session): session closed for user root May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 16 23:46:23 musicbox volumio[1002]: info: No need to fix Spotify hosts May 16 23:46:24 musicbox go-librespot[1391]: time="2025-05-16T23:46:24+02:00" level=info msg="running go-librespot 0.2.0" May 16 23:46:24 musicbox go-librespot[1391]: time="2025-05-16T23:46:24+02:00" level=debug msg="app state loaded" May 16 23:46:24 musicbox go-librespot[1391]: time="2025-05-16T23:46:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 16 23:46:24 musicbox volumio[1002]: info: [ROTARYENCODER2] addOverlay for Button: 4 true up May 16 23:46:24 musicbox volumio[1002]: info: [ROTARYENCODER2] addOverlay: executing command: /usr/bin/sudo /usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 & May 16 23:46:24 musicbox volumio[1002]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 16 23:46:24 musicbox volumio[1002]: SPOTIFY: BQBGDojCg-A5swfjDs32y0RtXb64WOvWEYF1nxR04aPYpJn_6EjLvqcpUaPihHTUz12zyuPwKADfhs0_ePFVe5gsJ0E1Tm6puqb9TmEuJ-KE0qmSrsqRDolKlQ_I2fO3-gxXuy2jbGn6t3-wysk3DbfP_SqNgaPoHEBIJSKHBwNExtt4o8Y59L4XdGGf2f4boAXNjFW4uhCuriXS_KWkNFc3zRjJZoHPMt98h0ESczC40KZ_djH_O_cvvy_hJglfKg7wT2L7g9Pgp-Ebl9O2lX1aopYVH640YTM3GQ2GwkpeSdgnLRM May 16 23:46:24 musicbox volumio[1002]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 16 23:46:24 musicbox volumio[1002]: info: New Spotify access token = BQBGDojCg-A5swfjDs32y0RtXb64WOvWEYF1nxR04aPYpJn_6EjLvqcpUaPihHTUz12zyuPwKADfhs0_ePFVe5gsJ0E1Tm6puqb9TmEuJ-KE0qmSrsqRDolKlQ_I2fO3-gxXuy2jbGn6t3-wysk3DbfP_SqNgaPoHEBIJSKHBwNExtt4o8Y59L4XdGGf2f4boAXNjFW4uhCuriXS_KWkNFc3zRjJZoHPMt98h0ESczC40KZ_djH_O_cvvy_hJglfKg7wT2L7g9Pgp-Ebl9O2lX1aopYVH640YTM3GQ2GwkpeSdgnLRM May 16 23:46:24 musicbox volumio[1002]: info: Spotify credentials grant success - running version from March 24, 2019 May 16 23:46:24 musicbox sudo[1409]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 16 23:46:24 musicbox sudo[1409]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:24 musicbox sudo[1409]: pam_unix(sudo:session): session closed for user root May 16 23:46:24 musicbox volumio[1002]: info: Starting Shairport Sync May 16 23:46:24 musicbox kernel: input: button@4 as /devices/platform/button@4/input/input1 May 16 23:46:24 musicbox volumio[1002]: info: Starting Shairport Sync May 16 23:46:24 musicbox volumio[1002]: info: Starting Shairport Sync May 16 23:46:25 musicbox sudo[1419]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 16 23:46:25 musicbox sudo[1419]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:25 musicbox sudo[1421]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 16 23:46:25 musicbox sudo[1421]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:25 musicbox sudo[1424]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 16 23:46:25 musicbox sudo[1424]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:25 musicbox volumio[1002]: info: CoreCommandRouter::volumioGetState May 16 23:46:25 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:25 musicbox volumio[1002]: info: CoreCommandRouter::volumioGetState May 16 23:46:25 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:25 musicbox systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 16 23:46:25 musicbox systemd[1]: shairport-sync.service: Succeeded. May 16 23:46:25 musicbox systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 16 23:46:25 musicbox systemd-udevd[1383]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+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]" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+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]" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+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]" May 16 23:46:25 musicbox systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 16 23:46:25 musicbox sudo[1419]: pam_unix(sudo:session): session closed for user root May 16 23:46:25 musicbox sudo[1421]: pam_unix(sudo:session): session closed for user root May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=info msg="zeroconf server listening on port 43877" May 16 23:46:25 musicbox sudo[1424]: pam_unix(sudo:session): session closed for user root May 16 23:46:25 musicbox volumio[1002]: info: Shairport-Sync Started May 16 23:46:25 musicbox volumio[1002]: Error adding Membership: Error: addMembership EINVAL May 16 23:46:25 musicbox volumio[1002]: info: Shairport-Sync Started May 16 23:46:25 musicbox volumio[1002]: info: Shairport-Sync Started May 16 23:46:25 musicbox volumio[1002]: info: /dev/input: May 16 23:46:25 musicbox volumio[1002]: by-path May 16 23:46:25 musicbox volumio[1002]: event0 May 16 23:46:25 musicbox volumio[1002]: event1 May 16 23:46:25 musicbox volumio[1002]: mice May 16 23:46:25 musicbox volumio[1002]: /dev/input/by-path: May 16 23:46:25 musicbox volumio[1002]: platform-button@4-event May 16 23:46:25 musicbox volumio[1002]: platform-rotary@17-event May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=debug msg="obtained new client token: AAAdXyb8Cv1YkfCcn3EPWAYWhMsBTUZXFh3naAHRSZ/MLzLwzwfii+sl+BKP6kAGfZMF6MGJmJMkJIQrrKtk4i5BEi+dri16dY7StzJl/etn7rxQH3D+J8scOnEQhlwkLc9PqgLoyunx2woWRJ9ZwQ41neXAscNKrYk4w0+G0421cNGtisx9UfnSkQRwvoKUy90GQRHA9mJQOgYXAJMK0o0KFsBK/yxntg3orv2wxNqVhrWciwZpjqbEKw==" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 16 23:46:25 musicbox sudo[1435]: 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 May 16 23:46:25 musicbox sudo[1435]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=debug msg="completed keyexchange" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=debug msg="completed challenge" May 16 23:46:25 musicbox kernel: CIFS: Attempting to mount //se-se01/internal/music May 16 23:46:25 musicbox volumio[1002]: 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/ab6775700000ee85346c5c7f5100ec893b77cef9","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82346c5c7f5100ec893b77cef9","width":64}],"product":"premium","type":"user","uri":"spotify:user:31bjkbz74djgmahibcw3dkhb6sha"} May 16 23:46:25 musicbox volumio[1002]: info: Spotify Successfully logged in May 16 23:46:25 musicbox volumio[1002]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 16 23:46:25 musicbox volumio[1002]: info: [1747431985714] CoreMusicLibrary::Adding element Spotify May 16 23:46:25 musicbox volumio[1002]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 16 23:46:25 musicbox volumio[1002]: Cannot find translation for source Spotify May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=info msg="authenticated AP as 31bjkbz74djgmahibcw3dkhb6sha" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=info msg="authenticated Login5 as 31bjkbz74djgmahibcw3dkhb6sha" May 16 23:46:25 musicbox go-librespot[1391]: time="2025-05-16T23:46:25+02:00" level=debug msg="initializing zeroconf session, username: 31bjkbz74djgmahibcw3dkhb6sha" May 16 23:46:25 musicbox mpd[1363]: May 16 23:46 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 16 23:46:25 musicbox systemd[1]: Started Music Player Daemon. May 16 23:46:25 musicbox volumio[1002]: Upnp client error: Error: This socket has been ended by the other party May 16 23:46:25 musicbox sudo[1328]: pam_unix(sudo:session): session closed for user root May 16 23:46:25 musicbox sudo[1345]: pam_unix(sudo:session): session closed for user root May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="dealer connection opened" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=trace msg="starting accesspoint recv loop" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=trace msg="starting dealer recv loop" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=trace msg="received accesspoint ping" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="received connection id: OTdhNDdjMDktNjZmOC00NmEyLTgwODgtYThjNjBhZWVmYzM1K2RlYWxlcit0Y3A6Ly8wYWIxNTdmYi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNTA2RDIyRjhGNEExQ0RBNEIyQzBGMkJGMDE5MDNEM0JFN0JENTI4NjJFMzBENzhGRDhBM0U1MjQ5NzQ5Rjc1RQ==" May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=trace msg="received accesspoint pong ack" May 16 23:46:26 musicbox volumio[1002]: error: MPD error: The expression evaluated to a falsy value: May 16 23:46:26 musicbox volumio[1002]: assert.ok(self.idling) May 16 23:46:26 musicbox volumio[1002]: error: The expression evaluated to a falsy value: May 16 23:46:26 musicbox volumio[1002]: assert.ok(self.idling) May 16 23:46:26 musicbox volumio[1002]: error: updateQueue error: null May 16 23:46:26 musicbox volumio[1002]: info: MPD running with PID1363 May 16 23:46:26 musicbox volumio[1002]: ,establishing connection May 16 23:46:26 musicbox go-librespot[1391]: time="2025-05-16T23:46:26+02:00" level=debug msg="put connect state because NEW_DEVICE" May 16 23:46:26 musicbox volumio[1002]: error: updateQueue error: null May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: 1,2,3 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: 1,2 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: 1 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: end of recursion. May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: rotary May 16 23:46:26 musicbox sudo[1446]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l May 16 23:46:26 musicbox sudo[1446]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:26 musicbox sudo[1446]: pam_unix(sudo:session): session closed for user root May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=23pinB=27 in Overlays (in load order): May 16 23:46:26 musicbox volumio[1002]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 May 16 23:46:26 musicbox volumio[1002]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: rotary 1 uses overlay 0 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: attach rotary 1 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-rotary@17-event, type: rotary May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: Checking for existing overlays for Rotary: 1 type: button May 16 23:46:26 musicbox volumio[1327]: Generating RSA private key, 4096 bit long modulus (2 primes) May 16 23:46:26 musicbox sudo[1462]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l May 16 23:46:26 musicbox sudo[1462]: pam_unix(sudo:session): session opened for user root by (uid=0) May 16 23:46:26 musicbox sudo[1462]: pam_unix(sudo:session): session closed for user root May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: check pinA=4pinB=undefined in Overlays (in load order): May 16 23:46:26 musicbox volumio[1002]: 0: rotary-encoder pin_a=23 pin_b=27 relative_axis=true steps-per-period=1 May 16 23:46:26 musicbox volumio[1002]: 1: gpio-key gpio=4 active_low=1 gpio_pull=up keycode=20 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] checkOverlayExists: button 1 uses overlay 1 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners: attach button 1 May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachListener: path: /dev/input/by-path/platform-button@4-event, type: button May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners rotaries: May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners buttons: May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners rotaries: May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] attachAllListeners buttons: May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] onStart: Attach Event-handles now. May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] Now addAllEventHandles for rotaries. May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: rotary May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] Now addAllEventHandles for buttons. May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] addEventHandle for rotary: 1 type: button May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] addEventHandle: adding handle : May 16 23:46:26 musicbox volumio[1002]: info: [ROTARYENCODER2] onStart: Plugin successfully started. May 16 23:46:26 musicbox volumio[1002]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 16 23:46:26 musicbox volumio[1002]: info: CoreCommandRouter::volumioRetrievevolume May 16 23:46:26 musicbox volumio[1002]: info: VolumeController:: Volume=30 Mute =false May 16 23:46:26 musicbox volumio[1002]: info: CoreCommandRouter::volumioGetState May 16 23:46:26 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:26 musicbox volumio[1002]: info: CoreStateMachine::pushState May 16 23:46:26 musicbox volumio[1002]: info: CorePlayQueue::getTrack 0 May 16 23:46:26 musicbox volumio[1002]: info: CoreCommandRouter::volumioPushState May 16 23:46:27 musicbox volumio[1002]: info: Completed starting Core Plugins May 16 23:46:27 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:46:27 musicbox volumio[1002]: info: ----- MyVolumio plugins startup ---- May 16 23:46:27 musicbox volumio[1002]: info: ------------------------------------------- May 16 23:46:27 musicbox volumio[1002]: info: [MyVolumio PluginManager] Fetching plans data.... May 16 23:46:27 musicbox volumio[1002]: info: go-librespot daemon successfully initialized May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="handling transfer player command from 4f6d92d4de3070df3f2f043297ebb8c579d5c8c8" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="fetched new page 0 with 19 items (list: 19)" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="shuffled context with seed 2425816942284009474 (len: 19, keep: 16)" uri="spotify:playlist:7uDbT77PcK6bu54y3jMTHx" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="loading track (paused: true, position: 2520ms)" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="emitting websocket event: will_play" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="selected format OGG_VORBIS_160 (84eb0e8e55b6229d23e0a47df9b284ac6ce29265)" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="requested aes key for file 84eb0e8e55b6229d23e0a47df9b284ac6ce29265, gid: 4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1711" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1300" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="fetched first chunk of 8, total size is 4055972 bytes" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="seek to 2520ms (diff: 2322ms, samples: 111132, bytes: 39955)" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="created new output device" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=info msg="loaded track \"Bright Eyes\" (paused: true, position: 2520ms, duration: 234813ms, prefetched: false)" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="emitting websocket event: metadata" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="emitting websocket event: active" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="sending successful reply for dealer request" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=trace msg="emitting websocket event: paused" May 16 23:46:28 musicbox go-librespot[1391]: time="2025-05-16T23:46:28+02:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:29 musicbox go-librespot[1391]: time="2025-05-16T23:46:29+02:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:30 musicbox volumio[1002]: info: Initializing connection to go-librespot Websocket May 16 23:46:30 musicbox go-librespot[1391]: time="2025-05-16T23:46:30+02:00" level=debug msg="new websocket client" May 16 23:46:30 musicbox volumio[1002]: info: Connection to go-librespot Websocket established May 16 23:46:31 musicbox volumio[1002]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=debug msg="handling resume player command from 4f6d92d4de3070df3f2f043297ebb8c579d5c8c8" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=trace msg="seek to 2520ms (diff: 142ms, samples: 111132, bytes: 39955)" uri="spotify:track:4NmLOTaaqdHQ9PUuoGrAWB" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+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" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=debug msg="resume track at 2378ms" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=trace msg="scheduling prefetch in 202s" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=debug msg="sending successful reply for dealer request" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 16 23:46:31 musicbox go-librespot[1391]: time="2025-05-16T23:46:31+02:00" level=trace msg="emitting websocket event: playing" May 16 23:46:31 musicbox volumio[1002]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4NmLOTaaqdHQ9PUuoGrAWB","play_origin":"playlist"}} May 16 23:46:31 musicbox volumio[1002]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 16 23:46:31 musicbox volumio[1002]: TypeError: Cannot read property 'service' of undefined May 16 23:46:31 musicbox volumio[1002]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 16 23:46:31 musicbox volumio[1002]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 16 23:46:31 musicbox volumio[1002]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 16 23:46:31 musicbox volumio[1002]: at WebSocket.emit (events.js:315:20) May 16 23:46:31 musicbox volumio[1002]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 16 23:46:31 musicbox volumio[1002]: at Receiver.emit (events.js:315:20) May 16 23:46:31 musicbox volumio[1002]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 16 23:46:31 musicbox volumio[1002]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 16 23:46:31 musicbox volumio[1002]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 16 23:46:31 musicbox volumio[1002]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 16 23:46:31 musicbox volumio[1002]: at writeOrBuffer (internal/streams/writable.js:358:12) May 16 23:46:31 musicbox volumio[1002]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 16 23:46:31 musicbox volumio[1002]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 16 23:46:31 musicbox volumio[1002]: at Socket.emit (events.js:315:20) May 16 23:46:31 musicbox volumio[1002]: at addChunk (internal/streams/readable.js:309:12) May 16 23:46:31 musicbox volumio[1002]: at readableAddChunk (internal/streams/readable.js:284:9) May 16 23:46:31 musicbox volumio[1002]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 16 23:46:32 musicbox sudo[1530]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-16 23:45 May 16 23:46:32 musicbox sudo[1530]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="a01a833dd28483f88cb390596f5090b7187992af" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 27 Feb 2025 11:42:54 AM CET" VOLUMIO_VERSION="3.795" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4049a67f1c09d4a94e033ba35a80a144"