-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-03-16 10:18:48 CET. -- Mar 16 10:18:19 volumio2 systemd-timedated[999]: Changed local time to Sun Mar 16 10:18:19 2025 Mar 16 10:18:19 volumio2 sudo[997]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:19 volumio2 volumio-time-update[568]: volumio-time-update-util: System time updated successfully. Mar 16 10:18:19 volumio2 systemd[1]: Started Volumio Time Update Utility. Mar 16 10:18:19 volumio2 volumio[967]: info: MYVOLUMIO Environment detected Mar 16 10:18:19 volumio2 volumio[967]: info: Plugin folders cleanup Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning into folder /volumio/app/plugins/ Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category audio_interface Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category miscellanea Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category music_service Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category plugins.json Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category system_controller Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category user_interface Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning into folder /data/plugins/ Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category audio_interface Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category music_service Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category system_controller Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category system_hardware Mar 16 10:18:19 volumio2 volumio[967]: info: Scanning category user_interface Mar 16 10:18:19 volumio2 volumio[967]: info: Plugin folders cleanup completed Mar 16 10:18:19 volumio2 volumio[967]: info: ------------------------------------------- Mar 16 10:18:19 volumio2 volumio[967]: info: ----- Core plugins startup ---- Mar 16 10:18:19 volumio2 volumio[967]: info: ------------------------------------------- Mar 16 10:18:19 volumio2 volumio[967]: info: Loading plugins from folder /volumio/app/plugins/ Mar 16 10:18:19 volumio2 volumio[967]: info: Adding plugin upnp to MyMusic Plugins Mar 16 10:18:19 volumio2 volumio[967]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 16 10:18:19 volumio2 volumio[967]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 16 10:18:19 volumio2 volumio[967]: info: Loading plugins from folder /data/plugins/ Mar 16 10:18:19 volumio2 volumio[967]: info: Loading plugin "system"... Mar 16 10:18:19 volumio2 volumio[967]: info: Loading plugin "appearance"... Mar 16 10:18:20 volumio2 nmbd[751]: [2025/03/16 10:18:20.487417, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 16 10:18:20 volumio2 systemd[1]: Started Samba NMB Daemon. Mar 16 10:18:20 volumio2 nmbd[751]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 16 10:18:20 volumio2 systemd[1]: Starting Samba Winbind Daemon... Mar 16 10:18:20 volumio2 nmbd[751]: [2025/03/16 10:18:20.512524, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Mar 16 10:18:20 volumio2 nmbd[751]: query_name_response: Multiple (2) responses received for a query on subnet 10.0.0.104 for name WORKGROUP<1d>. Mar 16 10:18:20 volumio2 nmbd[751]: This response was from IP 10.0.0.166, reporting an IP address of 10.0.0.166. Mar 16 10:18:20 volumio2 volumio-remote-updater[548]: [2025-03-16 10:18:20] [connect] Successful connection Mar 16 10:18:20 volumio2 winbindd[1006]: [2025/03/16 10:18:20.858004, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 16 10:18:20 volumio2 winbindd[1006]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 16 10:18:20 volumio2 winbindd[1006]: [2025/03/16 10:18:20.877384, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 16 10:18:20 volumio2 systemd[1]: Started Samba Winbind Daemon. Mar 16 10:18:20 volumio2 winbindd[1006]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 16 10:18:20 volumio2 systemd[1]: Starting Samba SMB Daemon... Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "network"... Mar 16 10:18:21 volumio2 volumio[967]: info: Refreshing Cached IP Addresses Mar 16 10:18:21 volumio2 sudo[1013]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 10:18:21 volumio2 sudo[1013]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:21 volumio2 sudo[1013]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:21 volumio2 sudo[1015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "services"... Mar 16 10:18:21 volumio2 sudo[1015]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "alsa_controller"... Mar 16 10:18:21 volumio2 sudo[1015]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:21 volumio2 sudo[1023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 16 10:18:21 volumio2 sudo[1023]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:21 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "wizard"... Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "networkfs"... Mar 16 10:18:21 volumio2 smbd[1011]: [2025/03/16 10:18:21.462751, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 16 10:18:21 volumio2 systemd[1]: Started Samba SMB Daemon. Mar 16 10:18:21 volumio2 smbd[1011]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 16 10:18:21 volumio2 systemd[1]: Reached target Multi-User System. Mar 16 10:18:21 volumio2 systemd[1]: Reached target Graphical Interface. Mar 16 10:18:21 volumio2 systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 16 10:18:21 volumio2 volumio[967]: info: Starting Udev Watcher for removable devices Mar 16 10:18:21 volumio2 sudo[1047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=volumio,password=1QAY2wsx3edc4rfv!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //10.0.0.189/volumio /mnt/NAS/Volumio@WDNAS-3 Mar 16 10:18:21 volumio2 sudo[1047]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:21 volumio2 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 16 10:18:21 volumio2 systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 16 10:18:21 volumio2 systemd[1]: Startup finished in 13.183s (kernel) + 28.224s (userspace) = 41.408s. Mar 16 10:18:21 volumio2 volumio[967]: info: Ignoring mount for partition: VOLUMIO2 Mar 16 10:18:21 volumio2 volumio[967]: info: Ignoring mount for partition: volumio Mar 16 10:18:21 volumio2 volumio[967]: info: Ignoring mount for partition: volumio_data Mar 16 10:18:21 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "volumio_command_line_client"... Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "upnp"... Mar 16 10:18:21 volumio2 volumio[967]: info: [1742116701634] Starting Upmpd Daemon Mar 16 10:18:21 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "my_music"... Mar 16 10:18:21 volumio2 volumio[967]: info: Loading plugin "mpd"... Mar 16 10:18:21 volumio2 kernel: Key type cifs.spnego registered Mar 16 10:18:21 volumio2 kernel: Key type cifs.idmap registered Mar 16 10:18:21 volumio2 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. Mar 16 10:18:21 volumio2 kernel: CIFS: Attempting to mount //10.0.0.189/volumio Mar 16 10:18:21 volumio2 kernel: cryptd: max_cpu_qlen set to 1000 Mar 16 10:18:22 volumio2 volumio[967]: info: Loading plugin "upnp_browser"... Mar 16 10:18:22 volumio2 sudo[1047]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:22 volumio2 volumio[967]: info: Loading plugin "alarm-clock"... Mar 16 10:18:22 volumio2 volumio[967]: info: Loading plugin "airplay_emulation"... Mar 16 10:18:22 volumio2 volumio[967]: info: Starting Shairport Sync Mar 16 10:18:22 volumio2 volumio[967]: info: Loading plugin "last_100"... Mar 16 10:18:22 volumio2 volumio[967]: info: Loading plugin "webradio"... Mar 16 10:18:23 volumio2 volumio[967]: info: Loading plugin "i2s_dacs"... Mar 16 10:18:23 volumio2 volumio[967]: info: Loading plugin "volumiodiscovery"... Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** For more information see Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 10:18:23 volumio2 volumio[967]: *** WARNING *** For more information see Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** For more information see Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 10:18:23 volumio2 node[967]: *** WARNING *** For more information see Mar 16 10:18:23 volumio2 volumio[967]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 10:18:23 volumio2 volumio[967]: info: Discovery: Started advertising with name: Volumio2 Mar 16 10:18:23 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 10:18:23 volumio2 volumio[967]: info: Loading plugin "spop"... Mar 16 10:18:24 volumio2 volumio[967]: info: Loading plugin "youtube2"... Mar 16 10:18:24 volumio2 sudo[1023]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:26 volumio2 systemd[1]: systemd-fsckd.service: Succeeded. Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "outputs"... Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "albumart"... Mar 16 10:18:28 volumio2 volumio[967]: info: Plugin example_plugin is not enabled Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "inputs"... Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "updater_comm"... Mar 16 10:18:28 volumio2 volumio[967]: info: Plugin mpdemulation is not enabled Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "rest_api"... Mar 16 10:18:28 volumio2 sh[498]: timed out Mar 16 10:18:28 volumio2 dhcpcd[534]: timed out Mar 16 10:18:28 volumio2 sh[498]: dhcpcd exited Mar 16 10:18:28 volumio2 dhcpcd[534]: dhcpcd exited Mar 16 10:18:28 volumio2 sh[498]: ifup: failed to bring up eth0 Mar 16 10:18:28 volumio2 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 16 10:18:28 volumio2 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "websocket"... Mar 16 10:18:28 volumio2 volumio[967]: info: Starting Socket.io Server version 2.3.0 Mar 16 10:18:28 volumio2 volumio[967]: info: Loading plugin "fusiondsp"... Mar 16 10:18:28 volumio2 volumio[967]: Forking 3 albumart workers Mar 16 10:18:29 volumio2 volumio[967]: info: Applying required configuration parameters for plugin fusiondsp Mar 16 10:18:29 volumio2 volumio[967]: info: Plugin mpdoutput is not enabled Mar 16 10:18:29 volumio2 volumio[967]: info: Loading plugin "backup_restore"... Mar 16 10:18:29 volumio2 volumio[967]: Starting albumart workers Mar 16 10:18:29 volumio2 volumio[967]: info: Applying required configuration parameters for plugin backup_restore Mar 16 10:18:29 volumio2 volumio[967]: info: Plugin onkyo_control is not enabled Mar 16 10:18:29 volumio2 volumio[967]: Starting albumart workers Mar 16 10:18:29 volumio2 volumio[967]: info: Plugin peppymeterbasic is not enabled Mar 16 10:18:29 volumio2 volumio[967]: info: Plugin peppyspectrum is not enabled Mar 16 10:18:29 volumio2 volumio[967]: info: Plugin randomizer is not enabled Mar 16 10:18:29 volumio2 volumio[967]: info: Loading plugin "touch_display"... Mar 16 10:18:29 volumio2 volumio[967]: Starting albumart workers Mar 16 10:18:30 volumio2 systemd[1]: systemd-hostnamed.service: Succeeded. Mar 16 10:18:30 volumio2 volumio[967]: info: Applying required configuration parameters for plugin touch_display Mar 16 10:18:30 volumio2 volumio[967]: info: Loading i18n strings for locale de Mar 16 10:18:30 volumio2 volumio[967]: Updating browse sources language Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::initPlayerControls Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: Express server listening on port 3000 Mar 16 10:18:30 volumio2 volumio[967]: [Metrics] WebUI: 13s 128.41ms Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::resetVolumioState Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::getcurrentVolume Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::pushState Mar 16 10:18:30 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::volumioPushState Mar 16 10:18:30 volumio2 volumio[967]: info: Volumio Network Manager: Network status updated: 2 Mar 16 10:18:30 volumio2 volumio[967]: verbose: New Socket.io Connection to 10.0.0.104:3000 from 10.0.0.239 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 10:18:30 volumio2 volumio[967]: verbose: New Socket.io Connection to 10.0.0.104:3000 from 10.0.0.239 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 16 10:18:30 volumio2 volumio[967]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 16 10:18:30 volumio2 volumio[967]: info: Reloading queue from file Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::setRepeat null single undefined Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::pushState Mar 16 10:18:30 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::volumioPushState Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::setRandom true Mar 16 10:18:30 volumio2 volumio[967]: info: CoreStateMachine::pushState Mar 16 10:18:30 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 10:18:30 volumio2 volumio[967]: info: CoreCommandRouter::volumioPushState Mar 16 10:18:30 volumio2 volumio[967]: info: Setting Device type: Raspberry PI Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: adding 6d594ed8-b778-4d61-b85a-ea5fa6038f51 Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: Found device Volumio2 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:31 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:31 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: adding 3ea5a15f-55c7-44b6-ae80-cbe98c591a6e Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: Found device Volumio-SMSL Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: Connecting to remote: 10.0.0.239 Mar 16 10:18:31 volumio2 volumio[967]: info: Completed loading Core Plugins Mar 16 10:18:31 volumio2 volumio[967]: info: Preparing to generate the ALSA configuration file Mar 16 10:18:31 volumio2 volumio[967]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 16 10:18:31 volumio2 volumio[967]: info: Reading ALSA contributions from plugins. Mar 16 10:18:31 volumio2 volumio[967]: info: Discovery: Connected to remote: 10.0.0.239 Mar 16 10:18:31 volumio2 volumio[967]: info: Asound.conf file unchanged, so no further update is needed Mar 16 10:18:31 volumio2 volumio[967]: info: Output device has changed, restarting MPD Mar 16 10:18:31 volumio2 sudo[1159]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 10:18:31 volumio2 volumio[967]: info: Output device has changed, restarting Shairport Sync Mar 16 10:18:31 volumio2 sudo[1159]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:31 volumio2 sudo[1159]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:31 volumio2 sudo[1161]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 10:18:31 volumio2 sudo[1161]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 systemd[1]: Stopping Music Player Daemon... Mar 16 10:18:31 volumio2 volumio[967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 10:18:31 volumio2 volumio[967]: info: ___________ START PLUGINS ___________ Mar 16 10:18:31 volumio2 volumio[967]: info: ControllerMpd::onStart: Initializing MPD Mar 16 10:18:31 volumio2 volumio[967]: info: Creating MPD Configuration file Mar 16 10:18:31 volumio2 sudo[1168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 10:18:31 volumio2 sudo[1168]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 10:18:31 volumio2 volumio[967]: info: [1742116711348] CoreMusicLibrary::Adding element Medienserver Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:31 volumio2 sudo[1168]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:31 volumio2 sudo[1170]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 10:18:31 volumio2 sudo[1170]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:31 volumio2 systemd[1]: mpd.service: Succeeded. Mar 16 10:18:31 volumio2 systemd[1]: Stopped Music Player Daemon. Mar 16 10:18:31 volumio2 volumio[967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 10:18:31 volumio2 volumio[967]: info: [1742116711494] CoreMusicLibrary::Adding element Last_100 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 10:18:31 volumio2 volumio[967]: info: [1742116711498] CoreMusicLibrary::Adding element Webradio Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 10:18:31 volumio2 volumio[967]: info: Initializing BBC Radios Mar 16 10:18:31 volumio2 systemd[1]: Starting Music Player Daemon... Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: Creating Spotify config file Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:31 volumio2 sudo[1191]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 10:18:31 volumio2 sudo[1191]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 sudo[1191]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 10:18:31 volumio2 volumio[967]: info: [1742116711669] CoreMusicLibrary::Adding element YouTube2 Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:31 volumio2 volumio[967]: Cannot find translation for source YouTube2 Mar 16 10:18:31 volumio2 volumio[967]: info: Loading i18n strings for locale de Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:31 volumio2 volumio[967]: info: FusionDsp - mixtype--------------------- None Mar 16 10:18:31 volumio2 volumio[967]: info: Loading i18n strings for locale de Mar 16 10:18:31 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 10:18:31 volumio2 volumio[967]: info: Volumio Calling Home Mar 16 10:18:31 volumio2 volumio[967]: info: Preparing to generate the ALSA configuration file Mar 16 10:18:31 volumio2 sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Mar 16 10:18:31 volumio2 sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Mar 16 10:18:31 volumio2 sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Mar 16 10:18:31 volumio2 sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:31 volumio2 systemd[1]: Reloading. Mar 16 10:18:32 volumio2 sudo[1219]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 10:18:32 volumio2 sudo[1219]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:32 volumio2 sudo[1219]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:32 volumio2 volumio[967]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Mar 16 10:18:32 volumio2 volumio[967]: info: Reading ALSA contributions from plugins. Mar 16 10:18:32 volumio2 volumio[967]: error: touch_display: Error detecting backlight interface: Error: ENOENT: no such file or directory, scandir '/sys/class/backlight/' Mar 16 10:18:32 volumio2 sudo[1222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 10:18:32 volumio2 sudo[1222]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:32 volumio2 sudo[1222]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:32 volumio2 volumio[967]: info: MPD Permissions set Mar 16 10:18:32 volumio2 volumio[967]: info: MPD Permissions set Mar 16 10:18:32 volumio2 volumio[967]: info: Volumio called home Mar 16 10:18:32 volumio2 volumio[967]: info: Spotify config file written Mar 16 10:18:32 volumio2 volumio[967]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 16 10:18:32 volumio2 sudo[1238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 10:18:32 volumio2 sudo[1238]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:32 volumio2 volumio[967]: info: No need to fix Spotify hosts Mar 16 10:18:32 volumio2 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. Mar 16 10:18:32 volumio2 volumio[967]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Mar 16 10:18:32 volumio2 sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Mar 16 10:18:32 volumio2 sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:32 volumio2 volumio[967]: info: Starting Shairport Sync Mar 16 10:18:32 volumio2 sudo[1249]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:32 volumio2 volumio[967]: info: Starting Shairport Sync Mar 16 10:18:32 volumio2 sudo[1252]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 10:18:32 volumio2 volumio[967]: info: Starting Shairport Sync Mar 16 10:18:32 volumio2 sudo[1252]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:32 volumio2 systemd[1]: Reloading. Mar 16 10:18:32 volumio2 volumio[967]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 16 10:18:32 volumio2 volumio[967]: SPOTIFY: BQBwdeaTzvm6DqLNfmbQJ9KvcxAOc7I4ttsULyLkjQ9VfjJVT55pBSyTtbMTJqnOiFY2JRhmBz7gW1ET6Lpba7CDpUU3gUJv6DrNXdKm3GOJJlJk1pJhpF0oNNUK03c1TPdwhX16agNld_rWiXgABzwf740vaEZkxysApEWcIJXIeFKqYMP0eBnvszkemgi5UwfPJi40gNpQEloOt4cQPBfpNuhk5XG6sAzHbrW0KlcfbIqZ66Ng08wUOK-IiQtVaEo1fL8b4KwUBtrLgBYnaCjjDGlj6ZuP1ZIlepw Mar 16 10:18:32 volumio2 volumio[967]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 16 10:18:32 volumio2 sudo[1215]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:33 volumio2 volumio[967]: info: New Spotify access token = BQBwdeaTzvm6DqLNfmbQJ9KvcxAOc7I4ttsULyLkjQ9VfjJVT55pBSyTtbMTJqnOiFY2JRhmBz7gW1ET6Lpba7CDpUU3gUJv6DrNXdKm3GOJJlJk1pJhpF0oNNUK03c1TPdwhX16agNld_rWiXgABzwf740vaEZkxysApEWcIJXIeFKqYMP0eBnvszkemgi5UwfPJi40gNpQEloOt4cQPBfpNuhk5XG6sAzHbrW0KlcfbIqZ66Ng08wUOK-IiQtVaEo1fL8b4KwUBtrLgBYnaCjjDGlj6ZuP1ZIlepw Mar 16 10:18:33 volumio2 sudo[1254]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 10:18:33 volumio2 volumio[967]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 16 10:18:33 volumio2 sudo[1254]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 sudo[1256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 10:18:33 volumio2 sudo[1256]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:33 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:33 volumio2 sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 10:18:33 volumio2 volumio[967]: info: touch_display: systemctl daemon-reload succeeded. Mar 16 10:18:33 volumio2 sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Mar 16 10:18:33 volumio2 sudo[1278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 16 10:18:33 volumio2 sudo[1278]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: info: Asound.conf file unchanged, so no further update is needed Mar 16 10:18:33 volumio2 volumio[967]: info: Output device has changed, restarting MPD Mar 16 10:18:33 volumio2 sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 10:18:33 volumio2 sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 sudo[1281]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:33 volumio2 volumio[967]: info: Output device has changed, restarting Shairport Sync Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:33 volumio2 sudo[1284]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 10:18:33 volumio2 sudo[1284]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 10:18:33 volumio2 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. Mar 16 10:18:33 volumio2 volumio[967]: info: MPD Permissions set Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: Starting Shairport Sync Mar 16 10:18:33 volumio2 sudo[1295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 10:18:33 volumio2 sudo[1295]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: SPOTIFY: User informations: {"country":"AT","display_name":"Walter.hoerner","email":"walter.hoerner@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/sdi3ff4vigkoeya8ibshzxneo"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/sdi3ff4vigkoeya8ibshzxneo","id":"sdi3ff4vigkoeya8ibshzxneo","images":[],"product":"premium","type":"user","uri":"spotify:user:sdi3ff4vigkoeya8ibshzxneo"} Mar 16 10:18:33 volumio2 volumio[967]: info: Spotify Successfully logged in Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 10:18:33 volumio2 volumio[967]: info: [1742116713557] CoreMusicLibrary::Adding element Spotify Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 10:18:33 volumio2 volumio[967]: Cannot find translation for source YouTube2 Mar 16 10:18:33 volumio2 volumio[967]: Cannot find translation for source Spotify Mar 16 10:18:33 volumio2 mpd[1205]: Mar 16 10:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 10:18:33 volumio2 volumio[967]: info: camilladsp spawned new process with pid 1305, instance 1, run: true Mar 16 10:18:33 volumio2 volumio[967]: info: camilladsp service started and running in background, instance 1 Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 10:18:33 volumio2 volumio[967]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 96000 <-AAAAAAAAAAAAA Mar 16 10:18:33 volumio2 volumio[967]: info: FusionDsp loaded Mar 16 10:18:33 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 16 10:18:33 volumio2 sudo[1309]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Mar 16 10:18:33 volumio2 sudo[1309]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:33 volumio2 volumio[967]: info: FusionDsp - Reporting Fusion DSP Enabled Mar 16 10:18:33 volumio2 volumio[967]: info: Adding Signal Path Element [object Object] Mar 16 10:18:33 volumio2 volumio[967]: info: Adding fusiondspeq DSP Signal Path Element Mar 16 10:18:33 volumio2 volumio[967]: info: FusionDsp - ---- installed callbackRead Mar 16 10:18:33 volumio2 volumio[967]: info: FusionDsp - If filter freq >samplerate/2 then disable it Mar 16 10:18:33 volumio2 systemd[1]: Started Music Player Daemon. Mar 16 10:18:33 volumio2 sudo[1170]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:33 volumio2 sudo[1212]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:33 volumio2 sudo[1161]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:33 volumio2 volumio[967]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 16 10:18:33 volumio2 volumio[967]: error: FusionDsp - WebSocket error: [object Object] Mar 16 10:18:33 volumio2 volumio[967]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Mar 16 10:18:34 volumio2 volumio[967]: error: MPD error: The expression evaluated to a falsy value: Mar 16 10:18:34 volumio2 volumio[967]: assert.ok(self.idling) Mar 16 10:18:34 volumio2 volumio[967]: error: The expression evaluated to a falsy value: Mar 16 10:18:34 volumio2 volumio[967]: assert.ok(self.idling) Mar 16 10:18:34 volumio2 volumio[967]: info: MPD running with PID1205 Mar 16 10:18:34 volumio2 volumio[967]: ,establishing connection Mar 16 10:18:34 volumio2 volumio[967]: error: updateQueue error: null Mar 16 10:18:34 volumio2 volumio[967]: error: updateQueue error: null Mar 16 10:18:34 volumio2 systemd[1]: Started FusionDsp Daemon. Mar 16 10:18:34 volumio2 sudo[1309]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 systemd[1]: Stopping Music Player Daemon... Mar 16 10:18:34 volumio2 systemd[1]: Started Volumio Kiosk. Mar 16 10:18:34 volumio2 sudo[1278]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 systemd[1]: Started UPnP Renderer front-end to MPD. Mar 16 10:18:34 volumio2 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 16 10:18:34 volumio2 sudo[1275]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 systemd[1]: Started go-librespot Daemon. Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: Volumio Kiosk started. Mar 16 10:18:34 volumio2 sudo[1238]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 go-librespot[1323]: go-librespot daemon starting... Mar 16 10:18:34 volumio2 systemd[1]: shairport-sync.service: Succeeded. Mar 16 10:18:34 volumio2 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 16 10:18:34 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:34 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:34 volumio2 systemd[1]: mpd.service: Succeeded. Mar 16 10:18:34 volumio2 systemd[1]: Stopped Music Player Daemon. Mar 16 10:18:34 volumio2 volumio[967]: info: Completed starting Core Plugins Mar 16 10:18:34 volumio2 volumio[967]: info: ------------------------------------------- Mar 16 10:18:34 volumio2 volumio[967]: info: ----- MyVolumio plugins startup ---- Mar 16 10:18:34 volumio2 volumio[967]: info: ------------------------------------------- Mar 16 10:18:34 volumio2 volumio[967]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 16 10:18:34 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:34 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:34 volumio2 sudo[1210]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 volumio[967]: info: Upmpdcli Daemon Started Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: X display number found: Mar 16 10:18:34 volumio2 systemd[1]: Starting Music Player Daemon... Mar 16 10:18:34 volumio2 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 16 10:18:34 volumio2 sudo[1256]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 sudo[1254]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 sudo[1295]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 sudo[1252]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 volumio[967]: info: Shairport-Sync Started Mar 16 10:18:34 volumio2 volumio[967]: Error adding Membership: Error: addMembership EINVAL Mar 16 10:18:34 volumio2 volumio[967]: info: Shairport-Sync Started Mar 16 10:18:34 volumio2 volumio[967]: info: Shairport-Sync Started Mar 16 10:18:34 volumio2 volumio[967]: info: Shairport-Sync Started Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: X display number found: 0 Mar 16 10:18:34 volumio2 sudo[1336]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 10:18:34 volumio2 sudo[1336]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:34 volumio2 sudo[1336]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: X display number found: 0 Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: X display number found: 0 Mar 16 10:18:34 volumio2 startx[1320]: X.Org X Server 1.20.4 Mar 16 10:18:34 volumio2 startx[1320]: X Protocol Version 11, Revision 0 Mar 16 10:18:34 volumio2 startx[1320]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Mar 16 10:18:34 volumio2 startx[1320]: Current Operating System: Linux volumio2 6.6.62-v7+ #1816 SMP Mon Nov 18 15:30:49 GMT 2024 armv7l Mar 16 10:18:34 volumio2 startx[1320]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=576 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 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=fb80cb44-b4d3-4b36-be35-613cba0a09fb imgfile=/volumio_current.sqsh bootpart=UUID=51B1-040D datapart=UUID=2899bccc-8620-4c7a-b56a-43fd2f7a836a 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 Mar 16 10:18:34 volumio2 startx[1320]: Build Date: 04 April 2023 07:50:56AM Mar 16 10:18:34 volumio2 startx[1320]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Mar 16 10:18:34 volumio2 startx[1320]: Current version of pixman: 0.36.0 Mar 16 10:18:34 volumio2 startx[1320]: Before reporting problems, check http://wiki.x.org Mar 16 10:18:34 volumio2 startx[1320]: to make sure that you have the latest version. Mar 16 10:18:34 volumio2 startx[1320]: Markers: (--) probed, (**) from config file, (==) default setting, Mar 16 10:18:34 volumio2 startx[1320]: (++) from command line, (!!) notice, (II) informational, Mar 16 10:18:34 volumio2 startx[1320]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Mar 16 10:18:34 volumio2 startx[1320]: (==) Log file: "/var/log/Xorg.0.log", Time: Sun Mar 16 10:18:34 2025 Mar 16 10:18:34 volumio2 startx[1320]: (==) Using config directory: "/etc/X11/xorg.conf.d" Mar 16 10:18:34 volumio2 startx[1320]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Mar 16 10:18:34 volumio2 volumio[967]: info: touch_display: X display number found: 0 Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=info msg="running go-librespot 0.2.0" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="app state loaded" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01: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]" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01: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]" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=info msg="zeroconf server listening on port 34003" Mar 16 10:18:35 volumio2 volumio-remote-updater[548]: [2025-03-16 10:18:35] [connect] Successful connection Mar 16 10:18:35 volumio2 volumio-remote-updater[548]: [2025-03-16 10:18:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1742116715 101 Mar 16 10:18:35 volumio2 volumio[967]: 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: 6 Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="obtained new client token: AAAkiNa0PTxtpjGtGDqGiy1I5SV1M/+jp2RWnKU0VMKzDXwrgGhvlGoahJMAE8gINKCv778L3HQlDFuncB08O2bmQTewdcyEhrgQ1xly4IxEfJSL6Ub30mtkvawwYtrM98ZnL6aP09ek9zfzGwJ+/D9Uk7wrGiYQCYrqTsKF56/8U3VASpogQFFv5ZAwwAY8OlavkgYSqJkYoTDRLKlXrWSJ2iwFBhoJdaMcIIvBKVgw1R4VGG35bnfQJb5v" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="completed keyexchange" Mar 16 10:18:35 volumio2 go-librespot[1323]: time="2025-03-16T10:18:35+01:00" level=debug msg="completed challenge" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=info msg="authenticated AP as sdi3ff4vigkoeya8ibshzxneo" Mar 16 10:18:36 volumio2 mpd[1358]: Mar 16 10:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 10:18:36 volumio2 systemd[1]: Started Music Player Daemon. Mar 16 10:18:36 volumio2 sudo[1284]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:36 volumio2 volumio[967]: error: updateQueue error: null Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=info msg="authenticated Login5 as sdi3ff4vigkoeya8ibshzxneo" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="initializing zeroconf session, username: sdi3ff4vigkoeya8ibshzxneo" Mar 16 10:18:36 volumio2 volumio[1322]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="dealer connection opened" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=trace msg="starting accesspoint recv loop" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=trace msg="starting dealer recv loop" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=trace msg="received accesspoint ping" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="received connection id: MTNiNjk0MDEtNjdkYi00OTY5LTlmOGMtZjY4YTcwYzE0Yzk4K2RlYWxlcit0Y3A6Ly8wYWNhNThiNS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArM0ZDNURERTM0ODU4MEEyMTRBQjZCNDFBMjUzMTM5RDg5ODI5ODJBQTUwMzAwMjU1RDFEQkUwODJDMjU1MkI2MQ==" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=trace msg="received accesspoint pong ack" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 16 10:18:36 volumio2 go-librespot[1323]: time="2025-03-16T10:18:36+01:00" level=debug msg="update volume to 65535/65535" Mar 16 10:18:37 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:37 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:37 volumio2 volumio[967]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 16 10:18:37 volumio2 volumio[967]: info: go-librespot daemon successfully initialized Mar 16 10:18:38 volumio2 go-librespot[1323]: time="2025-03-16T10:18:38+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 10:18:38 volumio2 go-librespot[1323]: time="2025-03-16T10:18:38+01:00" level=trace msg="emitting websocket event: volume" Mar 16 10:18:39 volumio2 volumio[967]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 16 10:18:40 volumio2 volumio[967]: info: Initializing connection to go-librespot Websocket Mar 16 10:18:40 volumio2 go-librespot[1323]: time="2025-03-16T10:18:40+01:00" level=debug msg="new websocket client" Mar 16 10:18:40 volumio2 volumio[1322]: .................................++++ Mar 16 10:18:40 volumio2 volumio[967]: info: Connection to go-librespot Websocket established Mar 16 10:18:42 volumio2 volumio[1322]: ..............++++ Mar 16 10:18:42 volumio2 volumio[1322]: e is 65537 (0x010001) Mar 16 10:18:42 volumio2 volumio[1322]: writing RSA key Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin bluetooth to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin multiroom to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin metavolumio to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin cd_controller to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 16 10:18:43 volumio2 volumio[967]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 16 10:18:44 volumio2 go-librespot[1323]: time="2025-03-16T10:18:44+01:00" level=debug msg="handling transfer player command from 25ea767d55768aa98e93d14e166459caf6849450" Mar 16 10:18:44 volumio2 go-librespot[1323]: time="2025-03-16T10:18:44+01:00" level=debug msg="resolved context of track" uri="spotify:album:3LXOrVXLXwRiOguE446OZo" Mar 16 10:18:44 volumio2 go-librespot[1323]: time="2025-03-16T10:18:44+01:00" level=trace msg="fetched new page 0 with 9 items (list: 9)" uri="spotify:album:3LXOrVXLXwRiOguE446OZo" Mar 16 10:18:44 volumio2 go-librespot[1323]: time="2025-03-16T10:18:44+01:00" level=debug msg="loading track (paused: true, position: 125085ms)" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:45 volumio2 volumio[967]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 16 10:18:45 volumio2 volumio[967]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 16 10:18:45 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:45 volumio2 volumio[967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 10:18:45 volumio2 volumio[967]: info: Starting MyVolumio Remote Streaming Endpoints Mar 16 10:18:45 volumio2 volumio[967]: info: MyVolumio login type: Token Mar 16 10:18:45 volumio2 volumio[967]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 16 10:18:45 volumio2 volumio[967]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=trace msg="emitting websocket event: will_play" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="selected format OGG_VORBIS_320 (8fd4e8f1e3098d79f9f1c7cf4f3cccbb0218ee40)" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="requested aes key for file 8fd4e8f1e3098d79f9f1c7cf4f3cccbb0218ee40, gid: 7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1379" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1134" Mar 16 10:18:45 volumio2 go-librespot[1323]: time="2025-03-16T10:18:45+01:00" level=debug msg="fetched first chunk of 31, total size is 15786452 bytes" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 3/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 10/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 11/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 9/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=trace msg="seek to 125085ms (diff: 45ms, samples: 5516248, bytes: 4943360)" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="created new output device" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=info msg="loaded track \"Catch The Rainbow\" (paused: true, position: 125085ms, duration: 396466ms, prefetched: false)" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 1/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 2/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="fetched chunk 12/30, size: 524288" uri="spotify:track:7FtRUrOEDUHTvenvp1BqZo" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=trace msg="emitting websocket event: metadata" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=trace msg="emitting websocket event: active" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="sending successful reply for dealer request" Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 16 10:18:46 volumio2 go-librespot[1323]: time="2025-03-16T10:18:46+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 16 10:18:47 volumio2 volumio[967]: info: Starting Streaming Service Transparent Proxy Mar 16 10:18:47 volumio2 volumio[967]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 16 10:18:47 volumio2 volumio[967]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 16 10:18:47 volumio2 volumio[967]: info: Streaming services startup Mar 16 10:18:47 volumio2 volumio[967]: info: Starting Streaming Daemon Mar 16 10:18:47 volumio2 go-librespot[1323]: time="2025-03-16T10:18:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 10:18:47 volumio2 volumio[967]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 16 10:18:47 volumio2 go-librespot[1323]: time="2025-03-16T10:18:47+01:00" level=trace msg="emitting websocket event: paused" Mar 16 10:18:47 volumio2 volumio[967]: info: Getting Spotify volume Mar 16 10:18:47 volumio2 volumio[967]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7FtRUrOEDUHTvenvp1BqZo","play_origin":"album"}} Mar 16 10:18:47 volumio2 volumio[967]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7FtRUrOEDUHTvenvp1BqZo","name":"Catch The Rainbow","artist_names":["Rainbow"],"album_name":"Ritchie Blackmore's Rainbow","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023626f32e555553b537a6493f","position":125085,"duration":396466,"release_date":"year:1975 month:1 day:1","track_number":4,"disc_number":1}} Mar 16 10:18:47 volumio2 volumio[967]: SPOTIFY: received: {"type":"active","data":null} Mar 16 10:18:47 volumio2 volumio[967]: info: Aligning Spotify Volume to Volumio Volume Mar 16 10:18:47 volumio2 volumio[967]: info: CoreCommandRouter::volumioGetState Mar 16 10:18:47 volumio2 volumio[967]: info: CorePlayQueue::getTrack 0 Mar 16 10:18:47 volumio2 volumio[967]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:7FtRUrOEDUHTvenvp1BqZo","play_origin":"album"}} Mar 16 10:18:47 volumio2 volumio[967]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 10:18:47 volumio2 volumio[967]: TypeError: Cannot read property 'service' of undefined Mar 16 10:18:47 volumio2 volumio[967]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 16 10:18:47 volumio2 volumio[967]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Mar 16 10:18:47 volumio2 volumio[967]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 16 10:18:47 volumio2 volumio[967]: at WebSocket.emit (events.js:315:20) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.emit (events.js:315:20) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 16 10:18:47 volumio2 volumio[967]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 16 10:18:47 volumio2 volumio[967]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 16 10:18:47 volumio2 volumio[967]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 16 10:18:47 volumio2 volumio[967]: at Socket.emit (events.js:315:20) Mar 16 10:18:47 volumio2 volumio[967]: at addChunk (internal/streams/readable.js:309:12) Mar 16 10:18:47 volumio2 volumio[967]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 16 10:18:47 volumio2 volumio[967]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 10:18:47 volumio2 sudo[1625]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 16 10:18:47 volumio2 sudo[1625]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 10:18:47 volumio2 sudo[1625]: pam_unix(sudo:session): session closed for user root Mar 16 10:18:48 volumio2 sudo[1646]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 10:17 Mar 16 10:18:48 volumio2 sudo[1646]: 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"