-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Thu 2025-04-17 12:54:14 CEST. -- Apr 17 12:53:59 volumio4 systemd-timedated[1077]: Changed local time to Thu Apr 17 12:53:59 2025 Apr 17 12:53:59 volumio4 sudo[1074]: pam_unix(sudo:session): session closed for user root Apr 17 12:53:59 volumio4 volumio-time-update[687]: volumio-time-update-util: System time updated successfully. Apr 17 12:53:59 volumio4 systemd[1]: Starting Daily man-db regeneration... Apr 17 12:53:59 volumio4 systemd[1]: Starting Daily apt download activities... Apr 17 12:53:59 volumio4 systemd[1]: Started Volumio Time Update Utility. Apr 17 12:53:59 volumio4 volumio[1039]: info: Loading plugin "appearance"... Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.888830, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 17 12:53:59 volumio4 systemd[1]: Started Samba NMB Daemon. Apr 17 12:53:59 volumio4 nmbd[796]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.933768, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Apr 17 12:53:59 volumio4 nmbd[796]: query_name_response: Multiple (2) responses received for a query on subnet 10.0.0.153 for name WORKGROUP<1d>. Apr 17 12:53:59 volumio4 nmbd[796]: This response was from IP 10.0.0.103, reporting an IP address of 10.0.0.103. Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.933965, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Apr 17 12:53:59 volumio4 nmbd[796]: query_name_response: Multiple (3) responses received for a query on subnet 10.0.0.153 for name WORKGROUP<1d>. Apr 17 12:53:59 volumio4 nmbd[796]: This response was from IP 10.0.0.76, reporting an IP address of 10.0.0.103. Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.946304, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Apr 17 12:53:59 volumio4 nmbd[796]: query_name_response: Multiple (4) responses received for a query on subnet 10.0.0.153 for name WORKGROUP<1d>. Apr 17 12:53:59 volumio4 nmbd[796]: This response was from IP 10.0.0.76, reporting an IP address of 10.0.0.103. Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.946543, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Apr 17 12:53:59 volumio4 nmbd[796]: query_name_response: Multiple (5) responses received for a query on subnet 10.0.0.153 for name WORKGROUP<1d>. Apr 17 12:53:59 volumio4 nmbd[796]: This response was from IP 10.0.0.76, reporting an IP address of 10.0.0.103. Apr 17 12:53:59 volumio4 nmbd[796]: [2025/04/17 12:53:59.946691, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Apr 17 12:53:59 volumio4 nmbd[796]: query_name_response: Multiple (6) responses received for a query on subnet 10.0.0.153 for name WORKGROUP<1d>. Apr 17 12:53:59 volumio4 nmbd[796]: This response was from IP 10.0.0.103, reporting an IP address of 10.0.0.103. Apr 17 12:53:59 volumio4 systemd[1]: Starting Samba Winbind Daemon... Apr 17 12:54:00 volumio4 winbindd[1101]: [2025/04/17 12:54:00.239689, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Apr 17 12:54:00 volumio4 winbindd[1101]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Apr 17 12:54:00 volumio4 winbindd[1101]: [2025/04/17 12:54:00.288409, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 17 12:54:00 volumio4 systemd[1]: Started Samba Winbind Daemon. Apr 17 12:54:00 volumio4 winbindd[1101]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Apr 17 12:54:00 volumio4 systemd[1]: Starting Samba SMB Daemon... Apr 17 12:54:00 volumio4 systemd[1]: man-db.service: Succeeded. Apr 17 12:54:00 volumio4 systemd[1]: Started Daily man-db regeneration. Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "network"... Apr 17 12:54:00 volumio4 volumio[1039]: info: Refreshing Cached IP Addresses Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "services"... Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "alsa_controller"... Apr 17 12:54:00 volumio4 sudo[1109]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 17 12:54:00 volumio4 sudo[1109]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:00 volumio4 sudo[1109]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:00 volumio4 sudo[1111]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 17 12:54:00 volumio4 sudo[1111]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:00 volumio4 sudo[1121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 17 12:54:00 volumio4 sudo[1111]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:00 volumio4 sudo[1121]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:00 volumio4 smbd[1106]: [2025/04/17 12:54:00.843312, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 17 12:54:00 volumio4 smbd[1106]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Apr 17 12:54:00 volumio4 systemd[1]: Started Samba SMB Daemon. Apr 17 12:54:00 volumio4 systemd[1]: Reached target Multi-User System. Apr 17 12:54:00 volumio4 systemd[1]: Reached target Graphical Interface. Apr 17 12:54:00 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "wizard"... Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "networkfs"... Apr 17 12:54:00 volumio4 systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 17 12:54:00 volumio4 volumio[1039]: info: Starting Udev Watcher for removable devices Apr 17 12:54:00 volumio4 sudo[1144]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //10.0.0.116/media /mnt/NAS/media Apr 17 12:54:00 volumio4 sudo[1144]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:00 volumio4 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 17 12:54:00 volumio4 systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 17 12:54:00 volumio4 volumio[1039]: info: Ignoring mount for partition: boot Apr 17 12:54:00 volumio4 volumio[1039]: info: Ignoring mount for partition: volumio Apr 17 12:54:00 volumio4 volumio[1039]: info: Ignoring mount for partition: volumio_data Apr 17 12:54:00 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "volumio_command_line_client"... Apr 17 12:54:00 volumio4 volumio[1039]: info: Plugin upnp is not enabled Apr 17 12:54:00 volumio4 volumio[1039]: info: Loading plugin "my_music"... Apr 17 12:54:00 volumio4 volumio-remote-updater[673]: [2025-04-17 12:54:00] [connect] Successful connection Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "mpd"... Apr 17 12:54:01 volumio4 kernel: Key type cifs.spnego registered Apr 17 12:54:01 volumio4 kernel: Key type cifs.idmap registered Apr 17 12:54:01 volumio4 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. Apr 17 12:54:01 volumio4 kernel: CIFS: Attempting to mount //10.0.0.116/media Apr 17 12:54:01 volumio4 kernel: cryptd: max_cpu_qlen set to 1000 Apr 17 12:54:01 volumio4 volumio[1039]: info: Plugin upnp_browser is not enabled Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "alarm-clock"... Apr 17 12:54:01 volumio4 systemd[1]: apt-daily.service: Succeeded. Apr 17 12:54:01 volumio4 systemd[1]: Started Daily apt download activities. Apr 17 12:54:01 volumio4 systemd[1]: Starting Daily apt upgrade and clean activities... Apr 17 12:54:01 volumio4 volumio[1039]: info: Plugin airplay_emulation is not enabled Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "last_100"... Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "webradio"... Apr 17 12:54:01 volumio4 sudo[1144]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "i2s_dacs"... Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "volumiodiscovery"... Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** For more information see Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 17 12:54:01 volumio4 volumio[1039]: *** WARNING *** For more information see Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** For more information see Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 17 12:54:01 volumio4 node[1039]: *** WARNING *** For more information see Apr 17 12:54:01 volumio4 volumio[1039]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 17 12:54:01 volumio4 volumio[1039]: info: Discovery: Started advertising with name: Volumio4 Apr 17 12:54:01 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 17 12:54:01 volumio4 volumio[1039]: info: Loading plugin "spop"... Apr 17 12:54:02 volumio4 systemd[1]: apt-daily-upgrade.service: Succeeded. Apr 17 12:54:02 volumio4 systemd[1]: Started Daily apt upgrade and clean activities. Apr 17 12:54:02 volumio4 systemd[1]: Startup finished in 11.927s (kernel) + 28.488s (userspace) = 40.415s. Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "outputs"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "albumart"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Plugin example_plugin is not enabled Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "inputs"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "updater_comm"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Plugin mpdemulation is not enabled Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "rest_api"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "websocket"... Apr 17 12:54:03 volumio4 volumio[1039]: info: Starting Socket.io Server version 2.3.0 Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading plugin "touch_display"... Apr 17 12:54:03 volumio4 volumio[1039]: Forking 3 albumart workers Apr 17 12:54:03 volumio4 volumio[1039]: info: Applying required configuration parameters for plugin touch_display Apr 17 12:54:03 volumio4 volumio[1039]: info: Loading i18n strings for locale de Apr 17 12:54:03 volumio4 volumio[1039]: Updating browse sources language Apr 17 12:54:03 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 17 12:54:03 volumio4 volumio[1039]: Starting albumart workers Apr 17 12:54:03 volumio4 volumio[1039]: Starting albumart workers Apr 17 12:54:03 volumio4 volumio[1039]: Starting albumart workers Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::initPlayerControls Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: Express server listening on port 3000 Apr 17 12:54:04 volumio4 volumio[1039]: [Metrics] WebUI: 6s 969.30ms Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::resetVolumioState Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::getcurrentVolume Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioRetrievevolume Apr 17 12:54:04 volumio4 volumio[1039]: info: Volumio Network Manager: Network status updated: 2 Apr 17 12:54:04 volumio4 volumio-remote-updater[673]: [2025-04-17 12:54:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1744887240 101 Apr 17 12:54:04 volumio4 volumio[1039]: 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 Apr 17 12:54:04 volumio4 wpa_supplicant[940]: RRM: Ignoring radio measurement request: Not RRM network Apr 17 12:54:04 volumio4 volumio[1039]: verbose: New Socket.io Connection to 10.0.0.153:3000 from 10.0.0.62 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Apr 17 12:54:04 volumio4 sudo[1121]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 17 12:54:04 volumio4 volumio[1039]: info: Discovery: Getting this device information Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 17 12:54:04 volumio4 volumio[1039]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Apr 17 12:54:04 volumio4 volumio[1039]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Apr 17 12:54:04 volumio4 volumio[1039]: info: Reloading queue from file Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: VolumeController:: Volume=100 Mute =false Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::pushState Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioPushState Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::updateTrackBlock Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrackBlock Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioRetrievevolume Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::setRepeat null single undefined Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::pushState Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioPushState Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::setRandom null Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreStateMachine::pushState Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioPushState Apr 17 12:54:04 volumio4 volumio[1039]: info: Setting Device type: Raspberry PI Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Apr 17 12:54:04 volumio4 volumio[1039]: info: Completed loading Core Plugins Apr 17 12:54:04 volumio4 volumio[1039]: info: Preparing to generate the ALSA configuration file Apr 17 12:54:04 volumio4 volumio[1039]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Apr 17 12:54:04 volumio4 volumio[1039]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Apr 17 12:54:04 volumio4 volumio[1039]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Apr 17 12:54:04 volumio4 volumio[1039]: verbose: New Socket.io Connection to 10.0.0.153:3000 from 10.0.0.148 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:04 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:04 volumio4 volumio[1039]: info: Asound.conf file unchanged, so no further update is needed Apr 17 12:54:04 volumio4 volumio[1039]: info: Output device has changed, restarting MPD Apr 17 12:54:04 volumio4 sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 17 12:54:04 volumio4 sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:04 volumio4 volumio[1039]: info: ___________ START PLUGINS ___________ Apr 17 12:54:04 volumio4 sudo[1331]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:04 volumio4 sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 17 12:54:04 volumio4 sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:04 volumio4 systemd[1]: Stopping Music Player Daemon... Apr 17 12:54:04 volumio4 volumio[1039]: info: ControllerMpd::onStart: Initializing MPD Apr 17 12:54:04 volumio4 volumio[1039]: info: Creating MPD Configuration file Apr 17 12:54:04 volumio4 sudo[1348]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 17 12:54:04 volumio4 sudo[1348]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 17 12:54:04 volumio4 volumio[1039]: info: [1744887244796] CoreMusicLibrary::Adding element Last_100 Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 17 12:54:04 volumio4 sudo[1348]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 17 12:54:04 volumio4 volumio[1039]: info: [1744887244807] CoreMusicLibrary::Adding element Webradio Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 17 12:54:04 volumio4 volumio[1039]: info: Initializing BBC Radios Apr 17 12:54:04 volumio4 sudo[1350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 17 12:54:04 volumio4 sudo[1350]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 17 12:54:04 volumio4 volumio[1039]: info: Creating Spotify config file Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:04 volumio4 systemd[1]: mpd.service: Succeeded. Apr 17 12:54:04 volumio4 systemd[1]: Stopped Music Player Daemon. Apr 17 12:54:04 volumio4 volumio[1039]: info: Loading i18n strings for locale de Apr 17 12:54:04 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 17 12:54:04 volumio4 volumio[1039]: info: Volumio Calling Home Apr 17 12:54:05 volumio4 systemd[1]: Starting Music Player Daemon... Apr 17 12:54:05 volumio4 sudo[1370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Apr 17 12:54:05 volumio4 sudo[1370]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 sudo[1368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Apr 17 12:54:05 volumio4 sudo[1372]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Apr 17 12:54:05 volumio4 sudo[1372]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 sudo[1368]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:05 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 17 12:54:05 volumio4 volumio[1039]: info: VolumeController:: Volume=100 Mute =false Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreStateMachine::pushState Apr 17 12:54:05 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioPushState Apr 17 12:54:05 volumio4 systemd[1]: Reloading. Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: adding c5dd068c-f15e-4f0e-8c47-605c1faa647f Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: Found device Volumio4 Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:05 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:05 volumio4 volumio[1039]: info: touch_display: Backlight interface detected. Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: adding c1995c81-d2fb-49b7-befe-5ac2dc40ec0f Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: Found device VolumioW Apr 17 12:54:05 volumio4 sudo[1363]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 17 12:54:05 volumio4 sudo[1363]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: Connecting to remote: 10.0.0.62 Apr 17 12:54:05 volumio4 sudo[1363]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:05 volumio4 volumio[1039]: info: MPD Permissions set Apr 17 12:54:05 volumio4 volumio[1039]: info: MPD Permissions set Apr 17 12:54:05 volumio4 volumio[1039]: info: Volumio called home Apr 17 12:54:05 volumio4 volumio[1039]: info: Spotify config file written Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:05 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:05 volumio4 volumio[1039]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Apr 17 12:54:05 volumio4 sudo[1391]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] CurState: stop PrevState: na Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] CurState: stop PrevState: na Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 17 12:54:05 volumio4 sudo[1391]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 17 12:54:05 volumio4 volumio[1039]: info: No need to fix Spotify hosts Apr 17 12:54:05 volumio4 volumio[1039]: info: Discovery: Connected to remote: 10.0.0.62 Apr 17 12:54:05 volumio4 systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 17 12:54:05 volumio4 sudo[1402]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/rpi_backlight/brightness Apr 17 12:54:05 volumio4 sudo[1402]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 volumio[1039]: info: touch_display: Raspberry Pi Foundation touch screen detected. Apr 17 12:54:05 volumio4 sudo[1402]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:05 volumio4 sudo[1405]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Apr 17 12:54:05 volumio4 sudo[1405]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] CurState: stop PrevState: na Apr 17 12:54:05 volumio4 volumio[1039]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 17 12:54:05 volumio4 sudo[1405]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:05 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:05 volumio4 volumio[1039]: info: touch_display: File permissions for backlight brightness control set. Apr 17 12:54:05 volumio4 volumio[1039]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Apr 17 12:54:05 volumio4 volumio[1039]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 17 12:54:05 volumio4 volumio[1039]: SPOTIFY: BQBOk5xZ1hxF-wg-FnqnKeAJaCwOq6LlNuoIMUonM-mORUIT5vzkoyrzTOA_UULbhs4K-0lXGz2EsJIiOZrRoYiIVyu801exoLZGkWiowCQmRTmMwfMpwCroiJ_lKPzpUfhGfXpC7DB5aFgHxupSxy7VUnLusEnORmyiNbLNX97sojPowrPpndWOEFaGjwPUBn-D7Xn449f05CP-Z8fq3tLuvxSJF1hcRf5ECTfj46_tZc-YkPqcTTzv1axa6NEBnaKAWswb86YtPLnJgbRwg8I Apr 17 12:54:05 volumio4 volumio[1039]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 17 12:54:05 volumio4 volumio[1039]: info: New Spotify access token = BQBOk5xZ1hxF-wg-FnqnKeAJaCwOq6LlNuoIMUonM-mORUIT5vzkoyrzTOA_UULbhs4K-0lXGz2EsJIiOZrRoYiIVyu801exoLZGkWiowCQmRTmMwfMpwCroiJ_lKPzpUfhGfXpC7DB5aFgHxupSxy7VUnLusEnORmyiNbLNX97sojPowrPpndWOEFaGjwPUBn-D7Xn449f05CP-Z8fq3tLuvxSJF1hcRf5ECTfj46_tZc-YkPqcTTzv1axa6NEBnaKAWswb86YtPLnJgbRwg8I Apr 17 12:54:05 volumio4 volumio[1039]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 17 12:54:05 volumio4 systemd[1]: ifup@eth0.service: Current command vanished from the unit file, execution of the command list won't be resumed. Apr 17 12:54:05 volumio4 volumio[1039]: SPOTIFY: User informations: {"country":"AT","display_name":"Wolfgang Wernhart","email":"wolfgang.wernhart@aon.at","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1138263555"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/1138263555","id":"1138263555","images":[{"height":300,"url":"https://scontent-lhr6-1.xx.fbcdn.net/v/t39.30808-1/464242923_8823478437710038_8812686133881254455_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=109&ccb=1-7&_nc_sid=79bf43&_nc_ohc=fiCwUG5NhOEQ7kNvwEGuvdU&_nc_oc=AdmiYIRZ75-_laQXEM5Kl00qjhGAtmK7ygKdaxBSgD5AMf7sS0aPKNurrZ_g5lVXqToGJJ2bn5JZN4u3B5m7D2D_&_nc_zt=24&_nc_ht=scontent-lhr6-1.xx&edm=AP4hL3IEAAAA&_nc_gid=6ZjfxoFkIk6CJqMFWniikg&oh=00_AfG5PcrUZKQglEBfyIFdWXK9mLV0L7cODH7X5E2D-AJs6A&oe=6806875D","width":300},{"height":64,"url":"https://scontent-lhr6-1.xx.fbcdn.net/v/t39.30808-1/464242923_8823478437710038_8812686133881254455_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=109&ccb=1-7&_nc_sid=fe756c&_nc_ohc=fiCwUG5NhOEQ7kNvwEGuvdU&_nc_oc=AdmiYIRZ75-_laQXEM5Kl00qjhGAtmK7ygKdaxBSgD5AMf7sS0aPKNurrZ_g5lVXqToGJJ2bn5JZN4u3B5m7D2D_&_nc_zt=24&_nc_ht=scontent-lhr6-1.xx&edm=AP4hL3IEAAAA&_nc_gid=6ZjfxoFkIk6CJqMFWniikg&oh=00_AfGVjtA51Xgia6yZhtmczWlJZylTV9081RkMMdQI0cOywA&oe=6806875D","width":64}],"product":"premium","type":"user","uri":"spotify:user:1138263555"} Apr 17 12:54:05 volumio4 volumio[1039]: info: Spotify Successfully logged in Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 17 12:54:05 volumio4 volumio[1039]: info: [1744887245601] CoreMusicLibrary::Adding element Spotify Apr 17 12:54:05 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 17 12:54:05 volumio4 volumio[1039]: Cannot find translation for source Spotify Apr 17 12:54:05 volumio4 systemd[1]: Reloading. Apr 17 12:54:05 volumio4 sudo[1372]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:05 volumio4 volumio[1039]: info: touch_display: systemctl daemon-reload succeeded. Apr 17 12:54:05 volumio4 sudo[1410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 17 12:54:05 volumio4 sudo[1410]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 12:54:05 volumio4 systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 17 12:54:06 volumio4 volumio[1039]: info: [ASDebug] Togle GPIO: OFF Apr 17 12:54:06 volumio4 sudo[1370]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: systemctl disable getty@tty1.service succeeded. Apr 17 12:54:06 volumio4 systemd[1]: Started Volumio Kiosk. Apr 17 12:54:06 volumio4 sudo[1410]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 systemd[1]: Started go-librespot Daemon. Apr 17 12:54:06 volumio4 sudo[1391]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: Volumio Kiosk started. Apr 17 12:54:06 volumio4 go-librespot[1427]: Librespot-go daemon starting... Apr 17 12:54:06 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:06 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:06 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:06 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:06 volumio4 sudo[1368]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: systemctl stop getty@tty1.service succeeded. Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: X display number found: Apr 17 12:54:06 volumio4 mpd[1408]: Apr 17 12:54 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: X display number found: 0 Apr 17 12:54:06 volumio4 startx[1426]: X.Org X Server 1.20.4 Apr 17 12:54:06 volumio4 startx[1426]: X Protocol Version 11, Revision 0 Apr 17 12:54:06 volumio4 startx[1426]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Apr 17 12:54:06 volumio4 startx[1426]: Current Operating System: Linux volumio4 6.6.62-v7l+ #1816 SMP Mon Nov 18 15:33:33 GMT 2024 armv7l Apr 17 12:54:06 volumio4 startx[1426]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=D8:3A:DD:13:D2:03 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=8543fa12-4125-4451-a534-cec5480e0606 imgfile=/volumio_current.sqsh bootpart=UUID=9C48-E5A3 datapart=UUID=f7cca1c6-391b-47a8-9c19-3b1948539def uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Apr 17 12:54:06 volumio4 startx[1426]: Build Date: 04 April 2023 07:50:56AM Apr 17 12:54:06 volumio4 startx[1426]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Apr 17 12:54:06 volumio4 startx[1426]: Current version of pixman: 0.36.0 Apr 17 12:54:06 volumio4 startx[1426]: Before reporting problems, check http://wiki.x.org Apr 17 12:54:06 volumio4 startx[1426]: to make sure that you have the latest version. Apr 17 12:54:06 volumio4 startx[1426]: Markers: (--) probed, (**) from config file, (==) default setting, Apr 17 12:54:06 volumio4 startx[1426]: (++) from command line, (!!) notice, (II) informational, Apr 17 12:54:06 volumio4 startx[1426]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Apr 17 12:54:06 volumio4 startx[1426]: (==) Log file: "/var/log/Xorg.0.log", Time: Thu Apr 17 12:54:06 2025 Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 17 12:54:06 volumio4 startx[1426]: (==) Using config directory: "/etc/X11/xorg.conf.d" Apr 17 12:54:06 volumio4 startx[1426]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Apr 17 12:54:06 volumio4 wpa_supplicant[940]: RRM: Ignoring radio measurement request: Not RRM network Apr 17 12:54:06 volumio4 volumio[1039]: info: touch_display: X display number found: 0 Apr 17 12:54:06 volumio4 go-librespot[1427]: time="2025-04-17T12:54:06+02:00" level=info msg="generated new device id: 248b4ec2fc850dd5427b2c33ab7c58d09dfecce1" Apr 17 12:54:06 volumio4 go-librespot[1427]: time="2025-04-17T12:54:06+02:00" level=debug msg="stored credentials found for 1138263555" Apr 17 12:54:06 volumio4 systemd[1]: Started Music Player Daemon. Apr 17 12:54:06 volumio4 sudo[1333]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 sudo[1350]: pam_unix(sudo:session): session closed for user root Apr 17 12:54:06 volumio4 volumio[1039]: info: Completed starting Core Plugins Apr 17 12:54:06 volumio4 volumio[1039]: info: ------------------------------------------- Apr 17 12:54:06 volumio4 volumio[1039]: info: ----- MyVolumio plugins startup ---- Apr 17 12:54:06 volumio4 volumio[1039]: info: ------------------------------------------- Apr 17 12:54:06 volumio4 volumio[1039]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 17 12:54:07 volumio4 volumio[1039]: error: MPD error: The expression evaluated to a falsy value: Apr 17 12:54:07 volumio4 volumio[1039]: assert.ok(self.idling) Apr 17 12:54:07 volumio4 volumio[1039]: error: The expression evaluated to a falsy value: Apr 17 12:54:07 volumio4 volumio[1039]: assert.ok(self.idling) Apr 17 12:54:07 volumio4 volumio[1039]: info: MPD running with PID1408 Apr 17 12:54:07 volumio4 volumio[1039]: ,establishing connection Apr 17 12:54:07 volumio4 volumio[1039]: error: updateQueue error: null Apr 17 12:54:07 volumio4 volumio[1039]: error: updateQueue error: null Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+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-gew1.spotify.com:80]" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02: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]" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02: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]" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=debug msg="zeroconf server listening on port 44801" Apr 17 12:54:07 volumio4 systemd[1]: systemd-fsckd.service: Succeeded. Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=debug msg="obtained new client token: AABEaG5er4uTkw1iw2AGgqJM/qDtS/J1FucGxjkDZ2X51KCuCXb5mF1DcRtY1BF/ZBFuCJbs3jrDVs28X0P3M6TjrvXl9ncBx816A313gamUOZhBMcjy9pxS7/RkZqaj5zg66nF4w4pZ7X90VT/K6RK0ri7g+Yaj0fmY7efVQ2oVaatyz7taawa3UniDUDhlfQvNyCursQfSWDDUcMjC9ML5ttK2oLCMVeySHCxv2KwzHc3PjVtveLwdaAk=" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=debug msg="completed keyexchange" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=debug msg="completed challenge" Apr 17 12:54:07 volumio4 go-librespot[1427]: time="2025-04-17T12:54:07+02:00" level=debug msg="authenticated as 1138263555" Apr 17 12:54:07 volumio4 sh[573]: timed out Apr 17 12:54:07 volumio4 dhcpcd[621]: timed out Apr 17 12:54:07 volumio4 sh[573]: dhcpcd exited Apr 17 12:54:07 volumio4 dhcpcd[621]: dhcpcd exited Apr 17 12:54:07 volumio4 sh[573]: ifup: failed to bring up eth0 Apr 17 12:54:07 volumio4 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Apr 17 12:54:07 volumio4 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Apr 17 12:54:07 volumio4 volumio[1039]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="authenticated as 1138263555" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="dealer connection opened" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="initializing zeroconf session, username: 1138263555" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="autoplay enabled: false" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="received connection id: N2Y0NDQ1NzgtZjc2Mi00MzcwLWI4MGQtYzM3NDY5YWZlZDdiK2RlYWxlcit0Y3A6Ly8wYWNhNTg0ZC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRTU1OERGODI4MEM5RDA3QkYyRjBFM0MzODA4RTBDMzBCQURDOUE1MDBEQTA5QUMwRjVDNjhDNzM0MDFGNjIzMA==" Apr 17 12:54:08 volumio4 go-librespot[1427]: time="2025-04-17T12:54:08+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 17 12:54:08 volumio4 wpa_supplicant[940]: RRM: Ignoring radio measurement request: Not RRM network Apr 17 12:54:09 volumio4 volumio[1039]: info: go-librespot daemon successfully initialized Apr 17 12:54:09 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 17 12:54:09 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 17 12:54:09 volumio4 volumio[1039]: info: Discovery: Getting this device information Apr 17 12:54:09 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:09 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:09 volumio4 volumio[1039]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 17 12:54:09 volumio4 systemd[1]: systemd-hostnamed.service: Succeeded. Apr 17 12:54:11 volumio4 wpa_supplicant[940]: RRM: Ignoring radio measurement request: Not RRM network Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="handling transfer player command from 22a6fd620bab82c8d695c10d94dcb4080e3d3d8e" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZEVXcEBcciyYNoZE" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=trace msg="fetched new page 0 with 30 items (list: 30)" uri="spotify:playlist:37i9dQZEVXcEBcciyYNoZE" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="loading track (paused: true, position: 98284ms)" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:12 volumio4 volumio[1039]: info: Initializing connection to go-librespot Websocket Apr 17 12:54:12 volumio4 volumio[1039]: info: Connection to go-librespot Websocket established Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="new websocket client" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=trace msg="emitting websocket event: will_play" Apr 17 12:54:12 volumio4 volumio[1039]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:47cNDW1xyM03mT2kseO41a","play_origin":"playlist"}} Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="selected format OGG_VORBIS_320 (c5a43f2a951cc2b2218db52888bbe71188d75b82)" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="requested aes key for file c5a43f2a951cc2b2218db52888bbe71188d75b82, gid: 47cNDW1xyM03mT2kseO41a" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3191" Apr 17 12:54:12 volumio4 volumio[1039]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2040" Apr 17 12:54:12 volumio4 go-librespot[1427]: time="2025-04-17T12:54:12+02:00" level=debug msg="fetched first chunk of 25, total size is 12824324 bytes" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 10/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 8/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=trace msg="seek to 98284ms (diff: 232ms, samples: 4334324, bytes: 4400363)" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="created new output device" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=info msg="loaded track \"Pretty Pimpin\" (paused: true, position: 98284ms, duration: 298760ms, prefetched: false)" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 11/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="fetched chunk 9/24, size: 524288" uri="spotify:track:47cNDW1xyM03mT2kseO41a" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=trace msg="emitting websocket event: metadata" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=trace msg="emitting websocket event: active" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="sending successful reply for dealer request" Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 17 12:54:13 volumio4 go-librespot[1427]: time="2025-04-17T12:54:13+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 17 12:54:14 volumio4 volumio[1039]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:47cNDW1xyM03mT2kseO41a","name":"Pretty Pimpin","artist_names":["Kurt Vile"],"album_name":"b'lieve i'm goin down...","album_cover_url":"https://i.scdn.co/image/ab67616d00001e025a4d0c41fe3f12fdd304b59f","position":98284,"duration":298760,"release_date":"year:2015 month:9 day:25","track_number":1,"disc_number":1}} Apr 17 12:54:14 volumio4 volumio[1039]: SPOTIFY: received: {"type":"active","data":null} Apr 17 12:54:14 volumio4 volumio[1039]: info: Aligning Spotify Volume to Volumio Volume Apr 17 12:54:14 volumio4 volumio[1039]: info: CoreCommandRouter::volumioGetState Apr 17 12:54:14 volumio4 volumio[1039]: info: CorePlayQueue::getTrack 0 Apr 17 12:54:14 volumio4 volumio[1039]: info: Setting Spotify Volume from Volumio: 100 Apr 17 12:54:14 volumio4 go-librespot[1427]: time="2025-04-17T12:54:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 17 12:54:14 volumio4 go-librespot[1427]: time="2025-04-17T12:54:14+02:00" level=trace msg="emitting websocket event: paused" Apr 17 12:54:14 volumio4 volumio[1039]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:47cNDW1xyM03mT2kseO41a","play_origin":"playlist"}} Apr 17 12:54:14 volumio4 volumio[1039]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 12:54:14 volumio4 volumio[1039]: TypeError: Cannot read property 'service' of undefined Apr 17 12:54:14 volumio4 volumio[1039]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Apr 17 12:54:14 volumio4 volumio[1039]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Apr 17 12:54:14 volumio4 volumio[1039]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Apr 17 12:54:14 volumio4 volumio[1039]: at WebSocket.emit (events.js:315:20) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver.emit (events.js:315:20) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Apr 17 12:54:14 volumio4 volumio[1039]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Apr 17 12:54:14 volumio4 volumio[1039]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 12:54:14 volumio4 sudo[1684]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-17 12:53 Apr 17 12:54:14 volumio4 sudo[1684]: 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="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"