-- Logs begin at Mon 2025-01-20 12:06:37 EET, end at Mon 2025-03-03 17:16:32 EET. -- Mar 03 17:16:14 volumio-el systemd-timedated[1055]: Changed local time to Mon Mar 3 17:16:14 2025 Mar 03 17:16:14 volumio-el sudo[1053]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:14 volumio-el volumio-time-update[602]: volumio-time-update-util: System time updated successfully. Mar 03 17:16:14 volumio-el systemd[1]: Started Volumio Time Update Utility. Mar 03 17:16:14 volumio-el systemd[1]: Starting Daily apt download activities... Mar 03 17:16:14 volumio-el ntpd[709]: Listen normally on 3 eth0 192.168.0.209:123 Mar 03 17:16:14 volumio-el ntpd[709]: Listen normally on 4 wlan0 192.168.0.208:123 Mar 03 17:16:14 volumio-el ntpd[709]: new interface(s) found: waking up resolver Mar 03 17:16:14 volumio-el systemd[1]: apt-daily.service: Succeeded. Mar 03 17:16:14 volumio-el systemd[1]: Started Daily apt download activities. Mar 03 17:16:14 volumio-el systemd[1]: Starting Daily apt upgrade and clean activities... Mar 03 17:16:15 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:15 volumio-el volumio[1031]: info: ----- Volumio3 ---- Mar 03 17:16:15 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:15 volumio-el volumio[1031]: info: ----- System startup ---- Mar 03 17:16:15 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:15 volumio-el systemd[1]: apt-daily-upgrade.service: Succeeded. Mar 03 17:16:15 volumio-el systemd[1]: Started Daily apt upgrade and clean activities. Mar 03 17:16:15 volumio-el volumio-remote-updater[596]: [2025-03-03 17:16:15] [connect] Successful connection Mar 03 17:16:15 volumio-el nmbd[696]: [2025/03/03 17:16:15.870321, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 03 17:16:15 volumio-el systemd[1]: Started Samba NMB Daemon. Mar 03 17:16:15 volumio-el nmbd[696]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 03 17:16:15 volumio-el volumio[1031]: info: MYVOLUMIO Environment detected Mar 03 17:16:15 volumio-el systemd[1]: Starting Samba Winbind Daemon... Mar 03 17:16:16 volumio-el volumio[1031]: info: Plugin folders cleanup Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning into folder /volumio/app/plugins/ Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category audio_interface Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category miscellanea Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category music_service Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category plugins.json Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category system_controller Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category user_interface Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning into folder /data/plugins/ Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category music_service Mar 03 17:16:16 volumio-el volumio[1031]: info: Scanning category user_interface Mar 03 17:16:16 volumio-el volumio[1031]: info: Plugin folders cleanup completed Mar 03 17:16:16 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:16 volumio-el volumio[1031]: info: ----- Core plugins startup ---- Mar 03 17:16:16 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:16 volumio-el volumio[1031]: info: Loading plugins from folder /volumio/app/plugins/ Mar 03 17:16:16 volumio-el volumio[1031]: info: Adding plugin upnp to MyMusic Plugins Mar 03 17:16:16 volumio-el volumio[1031]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 03 17:16:16 volumio-el volumio[1031]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 03 17:16:16 volumio-el volumio[1031]: info: Loading plugins from folder /data/plugins/ Mar 03 17:16:16 volumio-el volumio[1031]: info: Loading plugin "system"... Mar 03 17:16:16 volumio-el volumio[1031]: info: Loading plugin "appearance"... Mar 03 17:16:16 volumio-el winbindd[1162]: [2025/03/03 17:16:16.158377, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 03 17:16:16 volumio-el winbindd[1162]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 03 17:16:16 volumio-el winbindd[1162]: [2025/03/03 17:16:16.175708, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 03 17:16:16 volumio-el systemd[1]: Started Samba Winbind Daemon. Mar 03 17:16:16 volumio-el winbindd[1162]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 03 17:16:16 volumio-el systemd[1]: Starting Samba SMB Daemon... Mar 03 17:16:16 volumio-el smbd[1172]: [2025/03/03 17:16:16.606391, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 03 17:16:16 volumio-el systemd[1]: Started Samba SMB Daemon. Mar 03 17:16:16 volumio-el smbd[1172]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 03 17:16:16 volumio-el systemd[1]: Reached target Multi-User System. Mar 03 17:16:16 volumio-el systemd[1]: Reached target Graphical Interface. Mar 03 17:16:16 volumio-el systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 03 17:16:16 volumio-el systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 03 17:16:16 volumio-el systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 03 17:16:16 volumio-el systemd[1]: Startup finished in 11.978s (kernel) + 29.580s (userspace) = 41.558s. Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "network"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Refreshing Cached IP Addresses Mar 03 17:16:17 volumio-el sudo[1182]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 03 17:16:17 volumio-el sudo[1182]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:17 volumio-el sudo[1182]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:17 volumio-el sudo[1184]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 03 17:16:17 volumio-el sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:17 volumio-el sudo[1184]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "services"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "alsa_controller"... Mar 03 17:16:17 volumio-el sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 03 17:16:17 volumio-el sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:17 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "wizard"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "networkfs"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Starting Udev Watcher for removable devices Mar 03 17:16:17 volumio-el sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.238/USB /mnt/NAS/USB Mar 03 17:16:17 volumio-el sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:17 volumio-el volumio[1031]: info: Ignoring mount for partition: boot Mar 03 17:16:17 volumio-el volumio[1031]: info: Ignoring mount for partition: volumio Mar 03 17:16:17 volumio-el volumio[1031]: info: Ignoring mount for partition: volumio_data Mar 03 17:16:17 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "volumio_command_line_client"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "upnp"... Mar 03 17:16:17 volumio-el volumio[1031]: info: [1741014977471] Starting Upmpd Daemon Mar 03 17:16:17 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "my_music"... Mar 03 17:16:17 volumio-el volumio[1031]: info: Loading plugin "mpd"... Mar 03 17:16:17 volumio-el kernel: Key type cifs.spnego registered Mar 03 17:16:17 volumio-el kernel: Key type cifs.idmap registered Mar 03 17:16:17 volumio-el 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 03 17:16:17 volumio-el kernel: CIFS: Attempting to mount //192.168.0.238/USB Mar 03 17:16:17 volumio-el kernel: cryptd: max_cpu_qlen set to 1000 Mar 03 17:16:17 volumio-el sudo[1210]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:18 volumio-el volumio[1031]: info: Loading plugin "upnp_browser"... Mar 03 17:16:18 volumio-el volumio[1031]: info: Loading plugin "alarm-clock"... Mar 03 17:16:18 volumio-el kernel: hwmon hwmon1: Undervoltage detected! Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "airplay_emulation"... Mar 03 17:16:19 volumio-el volumio[1031]: info: Starting Shairport Sync Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "last_100"... Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "webradio"... Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "i2s_dacs"... Mar 03 17:16:19 volumio-el volumio[1031]: info: I2S DAC not set, start Auto-detection Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "volumiodiscovery"... Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** For more information see Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 03 17:16:19 volumio-el volumio[1031]: *** WARNING *** For more information see Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** For more information see Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 03 17:16:19 volumio-el node[1031]: *** WARNING *** For more information see Mar 03 17:16:19 volumio-el volumio[1031]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 03 17:16:19 volumio-el volumio[1031]: info: Discovery: Started advertising with name: Volumio EL Mar 03 17:16:19 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 03 17:16:19 volumio-el volumio[1031]: info: Loading plugin "bandcamp"... Mar 03 17:16:20 volumio-el sudo[1193]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:21 volumio-el volumio[1031]: info: Loading plugin "spop"... Mar 03 17:16:22 volumio-el systemd[1]: systemd-fsckd.service: Succeeded. Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "outputs"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "albumart"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Plugin example_plugin is not enabled Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "inputs"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "updater_comm"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Plugin mpdemulation is not enabled Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "rest_api"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "websocket"... Mar 03 17:16:22 volumio-el volumio[1031]: info: Starting Socket.io Server version 2.3.0 Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading plugin "Systeminfo"... Mar 03 17:16:22 volumio-el volumio[1031]: Forking 3 albumart workers Mar 03 17:16:22 volumio-el volumio[1031]: info: Loading i18n strings for locale en Mar 03 17:16:22 volumio-el volumio[1031]: Updating browse sources language Mar 03 17:16:22 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:22 volumio-el volumio[1031]: Starting albumart workers Mar 03 17:16:22 volumio-el volumio[1031]: Starting albumart workers Mar 03 17:16:22 volumio-el volumio[1031]: Starting albumart workers Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::initPlayerControls Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: Express server listening on port 3000 Mar 03 17:16:23 volumio-el volumio[1031]: [Metrics] WebUI: 8s 956.18ms Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreStateMachine::resetVolumioState Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreStateMachine::getcurrentVolume Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::volumioRetrievevolume Mar 03 17:16:23 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:23 volumio-el volumio[1031]: info: Volumio Network Manager: Network status updated: 3 Mar 03 17:16:23 volumio-el volumio[1031]: verbose: New Socket.io Connection to 192.168.0.209:3000 from 192.168.0.238 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 03 17:16:24 volumio-el volumio[1031]: info: Reloading queue from file Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Mar 03 17:16:24 volumio-el volumio[1031]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 03 17:16:24 volumio-el volumio[1031]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03114 Mar 03 17:16:24 volumio-el volumio[1031]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::setRepeat false single undefined Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::pushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioPushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::setRandom null Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::pushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioPushState Mar 03 17:16:24 volumio-el volumio[1031]: info: Setting Device type: Raspberry PI Mar 03 17:16:24 volumio-el volumio[1031]: info: VolumeController:: Volume=100 Mute =false Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::pushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioPushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::updateTrackBlock Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrackBlock Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioRetrievevolume Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioGetState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: adding 9f2d147f-1a73-46a7-b751-b17f67c3907d Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Found device Volumio KB Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Connecting to remote: 192.168.0.238 Mar 03 17:16:24 volumio-el volumio[1031]: info: VolumeController:: Volume=100 Mute =false Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreStateMachine::pushState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioPushState Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: this is already registered, 9f2d147f-1a73-46a7-b751-b17f67c3907d Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Found device Volumio KB Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Connecting to remote: 192.168.0.238 Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: adding 29c3c2ae-6ca7-4d0a-a821-f664e1daefd8 Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Found device Volumio EL Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioGetState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: Completed loading Core Plugins Mar 03 17:16:24 volumio-el volumio[1031]: info: Preparing to generate the ALSA configuration file Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: this is already registered, 29c3c2ae-6ca7-4d0a-a821-f664e1daefd8 Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Found device Volumio EL Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioGetState Mar 03 17:16:24 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:24 volumio-el volumio[1031]: info: Discovery: Connected to remote: 192.168.0.238 Mar 03 17:16:24 volumio-el volumio[1031]: info: Asound.conf file unchanged, so no further update is needed Mar 03 17:16:24 volumio-el volumio[1031]: info: Output device has changed, restarting MPD Mar 03 17:16:24 volumio-el sudo[1322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 03 17:16:24 volumio-el volumio[1031]: info: Output device has changed, restarting Shairport Sync Mar 03 17:16:24 volumio-el sudo[1322]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:24 volumio-el sudo[1322]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:24 volumio-el sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 03 17:16:24 volumio-el sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:24 volumio-el systemd[1]: Stopping Music Player Daemon... Mar 03 17:16:24 volumio-el volumio[1031]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 03 17:16:24 volumio-el volumio[1031]: info: ___________ START PLUGINS ___________ Mar 03 17:16:24 volumio-el volumio[1031]: info: ControllerMpd::onStart: Initializing MPD Mar 03 17:16:24 volumio-el volumio[1031]: info: Creating MPD Configuration file Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 03 17:16:24 volumio-el volumio[1031]: info: [1741014984682] CoreMusicLibrary::Adding element Media Servers Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:24 volumio-el sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 03 17:16:24 volumio-el sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:24 volumio-el sudo[1331]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:24 volumio-el sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 03 17:16:24 volumio-el sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:24 volumio-el systemd[1]: mpd.service: Succeeded. Mar 03 17:16:24 volumio-el systemd[1]: Stopped Music Player Daemon. Mar 03 17:16:24 volumio-el volumio[1031]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:24 volumio-el systemd[1]: Starting Music Player Daemon... Mar 03 17:16:24 volumio-el volumio[1031]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 03 17:16:24 volumio-el volumio[1031]: info: [1741014984877] CoreMusicLibrary::Adding element Last_100 Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 03 17:16:24 volumio-el volumio[1031]: info: [1741014984881] CoreMusicLibrary::Adding element Webradio Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 03 17:16:24 volumio-el volumio[1031]: info: Initializing BBC Radios Mar 03 17:16:24 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:25 volumio-el sudo[1339]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 03 17:16:25 volumio-el sudo[1339]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:25 volumio-el sudo[1339]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 03 17:16:25 volumio-el volumio[1031]: info: [1741014985018] CoreMusicLibrary::Adding element Bandcamp Discover Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:25 volumio-el volumio[1031]: Cannot find translation for source Bandcamp Discover Mar 03 17:16:25 volumio-el volumio[1031]: info: Creating Spotify config file Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: Volumio Calling Home Mar 03 17:16:25 volumio-el volumio[1031]: info: MPD Permissions set Mar 03 17:16:25 volumio-el volumio[1031]: info: MPD Permissions set Mar 03 17:16:25 volumio-el volumio[1031]: info: Spotify config file written Mar 03 17:16:25 volumio-el volumio[1031]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 03 17:16:25 volumio-el volumio[1031]: info: Volumio called home Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el sudo[1359]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el sudo[1359]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 03 17:16:25 volumio-el volumio[1031]: info: No need to fix Spotify hosts Mar 03 17:16:25 volumio-el systemd[1]: Started go-librespot Daemon. Mar 03 17:16:25 volumio-el sudo[1359]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:25 volumio-el systemd[1]: systemd-hostnamed.service: Succeeded. Mar 03 17:16:25 volumio-el go-librespot[1366]: Librespot-go daemon starting... Mar 03 17:16:25 volumio-el volumio[1031]: info: Starting Shairport Sync Mar 03 17:16:25 volumio-el volumio[1031]: info: Starting Shairport Sync Mar 03 17:16:25 volumio-el volumio[1031]: info: Starting Shairport Sync Mar 03 17:16:25 volumio-el sudo[1379]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 03 17:16:25 volumio-el sudo[1379]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:25 volumio-el sudo[1382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 03 17:16:25 volumio-el sudo[1382]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:25 volumio-el systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 03 17:16:25 volumio-el systemd[1]: shairport-sync.service: Succeeded. Mar 03 17:16:25 volumio-el systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 03 17:16:25 volumio-el sudo[1385]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 03 17:16:25 volumio-el sudo[1385]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:25 volumio-el volumio[1031]: info: CoreCommandRouter::volumioGetState Mar 03 17:16:25 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:26 volumio-el systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 03 17:16:26 volumio-el volumio[1031]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 03 17:16:26 volumio-el volumio[1031]: SPOTIFY: BQCMaesYW68p2UE87U1mai1JK1ZLslsmqtwRMIyKV8vVnPzJMl-K1EoL0YbjsiNomE5xqicedP2dOfF50qLh1jtpyTw2x2PXZkqA6ISJhiAaBkX-C1ljYaUmnpvFMx-R20e9lplTXocV9jNcllMdNdcEA5Ya0kWwZLXyhE-G_sojkHRP8yJw5_kvHwBPG-lS5jMU6TEVCYEjeFWQJKBSbU9GUbmhfH5mAHh5ZJ3qXjfQLbhG4-TT_MpCF4z6NKYUwKs4zkRd6Q4fQ6nrOzPlEMX87Shr1Ayk7MfXsIc Mar 03 17:16:26 volumio-el volumio[1031]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=info msg="generated new device id: 17bf2677ad7254739331d9576ff426f81827c955" Mar 03 17:16:26 volumio-el sudo[1379]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="stored credentials found for o4jztk6ypge4f89p4idwgzlmp" Mar 03 17:16:26 volumio-el volumio[1031]: info: New Spotify access token = BQCMaesYW68p2UE87U1mai1JK1ZLslsmqtwRMIyKV8vVnPzJMl-K1EoL0YbjsiNomE5xqicedP2dOfF50qLh1jtpyTw2x2PXZkqA6ISJhiAaBkX-C1ljYaUmnpvFMx-R20e9lplTXocV9jNcllMdNdcEA5Ya0kWwZLXyhE-G_sojkHRP8yJw5_kvHwBPG-lS5jMU6TEVCYEjeFWQJKBSbU9GUbmhfH5mAHh5ZJ3qXjfQLbhG4-TT_MpCF4z6NKYUwKs4zkRd6Q4fQ6nrOzPlEMX87Shr1Ayk7MfXsIc Mar 03 17:16:26 volumio-el volumio[1031]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 03 17:16:26 volumio-el systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 03 17:16:26 volumio-el systemd[1]: shairport-sync.service: Succeeded. Mar 03 17:16:26 volumio-el systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 03 17:16:26 volumio-el systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 03 17:16:26 volumio-el sudo[1385]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:26 volumio-el sudo[1382]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:26 volumio-el volumio[1031]: info: Shairport-Sync Started Mar 03 17:16:26 volumio-el volumio[1031]: Error adding Membership: Error: addMembership EINVAL Mar 03 17:16:26 volumio-el volumio[1031]: info: Shairport-Sync Started Mar 03 17:16:26 volumio-el volumio[1031]: SPOTIFY: User informations: {"country":"EE","display_name":"Lauri Sisask","email":"lauri.sisask@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/o4jztk6ypge4f89p4idwgzlmp"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/o4jztk6ypge4f89p4idwgzlmp","id":"o4jztk6ypge4f89p4idwgzlmp","images":[],"product":"premium","type":"user","uri":"spotify:user:o4jztk6ypge4f89p4idwgzlmp"} Mar 03 17:16:26 volumio-el volumio[1031]: info: Spotify Successfully logged in Mar 03 17:16:26 volumio-el volumio[1031]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 03 17:16:26 volumio-el volumio[1031]: info: [1741014986334] CoreMusicLibrary::Adding element Spotify Mar 03 17:16:26 volumio-el volumio[1031]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 03 17:16:26 volumio-el volumio[1031]: Cannot find translation for source Bandcamp Discover Mar 03 17:16:26 volumio-el volumio[1031]: Cannot find translation for source Spotify Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="zeroconf server listening on port 42659" Mar 03 17:16:26 volumio-el mpd[1354]: Mar 03 17:16 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 03 17:16:26 volumio-el systemd[1]: Started Music Player Daemon. Mar 03 17:16:26 volumio-el sudo[1333]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:26 volumio-el sudo[1324]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="obtained new client token: AAD65SbJmnEdjWJdivjMo4qTMJQ3W4CiRDXRROsdpTOnd5d/aXbT+bycFzlrLAbMtP4q7g3IFMkVn/x6fnAiGb5DlrNGJHNB4bzawqwUjHBSC47wvlo/A2rSy6hRgdXw3HLC3YZkg2DN9SqSGbCTRYnf9Ic8r6cD6SXb4tfdNYMBze/nEiDwY+ykSp+hx3Psb3/zu1Z+9i76XA0D/LIeEz/FRBJyaXByN80RShIjHlbmuAJL/hPgTJF49kLI" Mar 03 17:16:26 volumio-el volumio[1031]: info: Completed starting Core Plugins Mar 03 17:16:26 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:26 volumio-el volumio[1031]: info: ----- MyVolumio plugins startup ---- Mar 03 17:16:26 volumio-el volumio[1031]: info: ------------------------------------------- Mar 03 17:16:26 volumio-el volumio[1031]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=info msg="connected to ap-gew1.spotify.com:4070" Mar 03 17:16:26 volumio-el volumio[1031]: error: MPD error: The expression evaluated to a falsy value: Mar 03 17:16:26 volumio-el volumio[1031]: assert.ok(self.idling) Mar 03 17:16:26 volumio-el volumio[1031]: error: The expression evaluated to a falsy value: Mar 03 17:16:26 volumio-el volumio[1031]: assert.ok(self.idling) Mar 03 17:16:26 volumio-el volumio[1031]: info: MPD running with PID1354 Mar 03 17:16:26 volumio-el volumio[1031]: ,establishing connection Mar 03 17:16:26 volumio-el volumio[1031]: error: updateQueue error: null Mar 03 17:16:26 volumio-el go-librespot[1366]: time="2025-03-03T17:16:26+02:00" level=debug msg="completed keyexchange" Mar 03 17:16:26 volumio-el volumio[1031]: error: updateQueue error: null Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="completed challenge" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="authenticated as o4jztk6ypge4f89p4idwgzlmp" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="authenticated as o4jztk6ypge4f89p4idwgzlmp" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="dealer connection opened" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="initializing zeroconf session, username: o4jztk6ypge4f89p4idwgzlmp" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="autoplay enabled: false" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="received connection id: ZTI1Y2IyZWUtZjIzYS00ZWUzLWE5ZGYtNWRiOTdhYWQ3ZWFhK2RlYWxlcit0Y3A6Ly8wYWNhNDE1Yy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRjI3RENGOTg1NThFMEI5NDFBODM5NEIwMDM3MzI5MkVBRUYyMTEyMEQ0QTk3Rjk5Q0RDNDg4REE3OEY5OTVDRQ==" Mar 03 17:16:27 volumio-el go-librespot[1366]: time="2025-03-03T17:16:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Mar 03 17:16:27 volumio-el sudo[1415]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 03 17:16:27 volumio-el sudo[1415]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:27 volumio-el sudo[1415]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:27 volumio-el sudo[1419]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 03 17:16:27 volumio-el sudo[1419]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:27 volumio-el sudo[1419]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:27 volumio-el sudo[1424]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 03 17:16:27 volumio-el sudo[1424]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 03 17:16:27 volumio-el systemd[1]: Started UPnP Renderer front-end to MPD. Mar 03 17:16:27 volumio-el sudo[1424]: pam_unix(sudo:session): session closed for user root Mar 03 17:16:27 volumio-el volumio[1031]: info: Upmpdcli Daemon Started Mar 03 17:16:27 volumio-el volumio[1426]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 03 17:16:28 volumio-el volumio[1031]: info: go-librespot daemon successfully initialized Mar 03 17:16:29 volumio-el kernel: hwmon hwmon1: Voltage normalised Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.0.209:55524->104.199.65.9:4070: use of closed network connection" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=debug msg="obtained new client token: AAB7dJHiiKZ9ruSSVin2llBoukD9ohNFHExMjuhIG2thGB1lanmroOqUEBMPmWm+c0IiQomE29mrq529/xupO4NehvsfxmkQUh/blKjgHsLrUvq+ypiShjtcXHTYKidESRZhFa+xfYQt5nxe9/5PEoe2EUiI4B3swtrabz8D9C86e8ap8IIPkEQqgncxIkhz6h6y4atIYhqyLS1kN2LA8quyIYkX2zS+laq8A9jVIpxy31JIjf6qTNT4gqaM" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=info msg="connected to ap-gew1.spotify.com:4070" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=debug msg="completed keyexchange" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=debug msg="completed challenge" Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=debug msg="authenticated as doris_dreimann" Mar 03 17:16:30 volumio-el volumio-remote-updater[596]: [2025-03-03 17:16:30] [connect] Successful connection Mar 03 17:16:30 volumio-el volumio-remote-updater[596]: [2025-03-03 17:16:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741014990 101 Mar 03 17:16:30 volumio-el volumio[1031]: 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: 3 Mar 03 17:16:30 volumio-el go-librespot[1366]: time="2025-03-03T17:16:30+02:00" level=debug msg="authenticated as doris_dreimann" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="dealer connection opened" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=info msg="accepted zeroconf user doris_dreimann from Pixel 8a" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="autoplay enabled: false" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="received connection id: MjdhODAwMmUtNWQ2Yy00MTMxLWExYTMtNGJlNGE3NGYxMTE1K2RlYWxlcit0Y3A6Ly8wYWNhNDIzZS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMTM1MUQxODFCM0U3QTkxNTk1MzJBOTE3RUU3QjVERDYzMkQwMzQ3QTYwQUU4MzIyMDRBNkY4NTAzNUIxNTFGMw==" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="put connect state because NEW_DEVICE" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="handling transfer player command from 619b43deda22dadb9f3474eb611d0f8ff3fd8589" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="resolved context of track" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 1 with 10 items (list: 20)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 2 with 11 items (list: 31)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 3 with 12 items (list: 43)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 4 with 11 items (list: 54)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el volumio[1031]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 5 with 10 items (list: 64)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 6 with 1 items (list: 65)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 7 with 1 items (list: 66)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="fetched new page 8 with 9 items (list: 75)" uri="spotify:artist:5Ryxgm3uLvQOsw4H5ZpHDn" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="shuffled context with seed 15339875660534723799 (len: 75, keep: 13)" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="loading track (paused: true, position: 1470ms)" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:31 volumio-el volumio[1031]: info: Initializing connection to go-librespot Websocket Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="new websocket client" Mar 03 17:16:31 volumio-el volumio[1031]: info: Connection to go-librespot Websocket established Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=trace msg="emitting websocket event: will_play" Mar 03 17:16:31 volumio-el volumio[1031]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7xCQC2MgMpn29yK51u5KSl","play_origin":"free-tier-artist"}} Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="selected format OGG_VORBIS_320 (3c95dcb9f5b6a856e88366554c49c4c210b0bf04)" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="requested aes key for file 3c95dcb9f5b6a856e88366554c49c4c210b0bf04, gid: 7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:31 volumio-el go-librespot[1366]: time="2025-03-03T17:16:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1359" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1125" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="fetched first chunk of 22, total size is 11467640 bytes" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=trace msg="seek to 1470ms (diff: 85ms, samples: 64827, bytes: 53465)" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="created new output device" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=info msg="loaded track \"They Say I'm Different\" (paused: true, position: 1470ms, duration: 255040ms, prefetched: false)" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=trace msg="emitting websocket event: metadata" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=trace msg="emitting websocket event: active" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="sending successful reply for dealer request" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 03 17:16:32 volumio-el volumio[1031]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7xCQC2MgMpn29yK51u5KSl","name":"They Say I'm Different","artist_names":["Betty Davis"],"album_name":"They Say I'm Different","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026611da38bd413b157294e378","position":1470,"duration":255040,"release_date":"year:2008 month:12 day:22","track_number":6,"disc_number":1}} Mar 03 17:16:32 volumio-el volumio[1031]: SPOTIFY: received: {"type":"active","data":null} Mar 03 17:16:32 volumio-el volumio[1031]: info: Aligning Spotify Volume to Volumio Volume Mar 03 17:16:32 volumio-el volumio[1031]: info: CoreCommandRouter::volumioGetState Mar 03 17:16:32 volumio-el volumio[1031]: info: CorePlayQueue::getTrack 0 Mar 03 17:16:32 volumio-el volumio[1031]: info: Setting Spotify Volume from Volumio: 100 Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:7xCQC2MgMpn29yK51u5KSl" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 03 17:16:32 volumio-el go-librespot[1366]: time="2025-03-03T17:16:32+02:00" level=trace msg="emitting websocket event: paused" Mar 03 17:16:32 volumio-el volumio[1031]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:7xCQC2MgMpn29yK51u5KSl","play_origin":"free-tier-artist"}} Mar 03 17:16:32 volumio-el volumio[1031]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 03 17:16:32 volumio-el volumio[1031]: TypeError: Cannot read property 'service' of undefined Mar 03 17:16:32 volumio-el volumio[1031]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 03 17:16:32 volumio-el volumio[1031]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Mar 03 17:16:32 volumio-el volumio[1031]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 03 17:16:32 volumio-el volumio[1031]: at WebSocket.emit (events.js:315:20) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.emit (events.js:315:20) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 03 17:16:32 volumio-el volumio[1031]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 03 17:16:32 volumio-el volumio[1031]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 03 17:16:32 volumio-el volumio[1031]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 03 17:16:32 volumio-el volumio[1031]: at Socket.emit (events.js:315:20) Mar 03 17:16:32 volumio-el volumio[1031]: at addChunk (internal/streams/readable.js:309:12) Mar 03 17:16:32 volumio-el volumio[1031]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 03 17:16:32 volumio-el volumio[1031]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 03 17:16:32 volumio-el sudo[1451]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-03 17:15 Mar 03 17:16:32 volumio-el sudo[1451]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"