-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Sun 2025-06-22 05:19:52 UTC. -- Jun 22 05:19:06 volumio ntpd[697]: receive: Unexpected origin timestamp 0xeb70bbe3.c699d3fb does not match aorg 0000000000.00000000 from server@136.243.7.20 xmt 0xec0210ca.0e145f26 Jun 22 05:19:06 volumio ntpd[697]: receive: Unexpected origin timestamp 0xeb70bbe3.c671d6f2 does not match aorg 0000000000.00000000 from server@217.160.19.219 xmt 0xec0210ca.0debda19 Jun 22 05:19:06 volumio ntpd[697]: receive: Unexpected origin timestamp 0xeb70bbe3.c690de73 does not match aorg 0000000000.00000000 from server@193.158.22.13 xmt 0xec0210ca.0e9b034c Jun 22 05:19:06 volumio ntpd[697]: receive: Unexpected origin timestamp 0xeb70bbe3.c6a26005 does not match aorg 0000000000.00000000 from server@81.3.27.46 xmt 0xec0210ca.0e8c574e Jun 22 05:19:06 volumio systemd[1]: Starting Daily apt download activities... Jun 22 05:19:06 volumio smbd[821]: [2025/06/22 05:19:06.308361, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 22 05:19:06 volumio smbd[821]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 22 05:19:06 volumio systemd[1]: Started Samba SMB Daemon. Jun 22 05:19:06 volumio dockerd[734]: time="2025-06-22T05:19:06.630539917Z" level=info msg="Loading containers: done." Jun 22 05:19:07 volumio dockerd[734]: time="2025-06-22T05:19:07.377969596Z" level=info msg="Docker daemon" commit=87a90dc graphdriver(s)=devicemapper version=20.10.14 Jun 22 05:19:07 volumio dockerd[734]: time="2025-06-22T05:19:07.386810316Z" level=info msg="Daemon has completed initialization" Jun 22 05:19:07 volumio systemd[1]: Started Docker Application Container Engine. Jun 22 05:19:07 volumio dockerd[734]: time="2025-06-22T05:19:07.877001361Z" level=info msg="API listen on /var/run/docker.sock" Jun 22 05:19:07 volumio wireless.js[461]: Cleaning previous... Jun 22 05:19:08 volumio sudo[970]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jun 22 05:19:08 volumio sudo[970]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:08 volumio sudo[970]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:08 volumio sudo[972]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jun 22 05:19:08 volumio sudo[972]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:08 volumio mpd[653]: Jun 22 05:19 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 22 05:19:09 volumio sudo[972]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:09 volumio wireless.js[461]: Stopped aP Jun 22 05:19:09 volumio wireless.js[461]: Wireless Networking DISABLED, not starting wireless flow Jun 22 05:19:09 volumio systemd[1]: wireless.service: Succeeded. Jun 22 05:19:09 volumio systemd[1]: Started Wireless Services. Jun 22 05:19:09 volumio systemd[1]: Started Volumio Backend Module. Jun 22 05:19:09 volumio mpd[653]: Jun 22 05:19 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jun 22 05:19:09 volumio mpd[653]: Jun 22 05:19 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jun 22 05:19:09 volumio systemd[1]: Started Music Player Daemon. Jun 22 05:19:09 volumio systemd[1]: Reached target Multi-User System. Jun 22 05:19:09 volumio systemd[1]: Reached target Graphical Interface. Jun 22 05:19:09 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 22 05:19:09 volumio volumio-remote-updater[451]: [2025-06-22 05:19:09] [info] asio async_connect error: system:111 (Connection refused) Jun 22 05:19:09 volumio volumio-remote-updater[451]: [2025-06-22 05:19:09] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 22 05:19:09 volumio volumio-remote-updater[451]: [2025-06-22 05:19:09] [error] handle_connect error: Underlying Transport Error Jun 22 05:19:09 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 22 05:19:09 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 22 05:19:12 volumio systemd[1]: apt-daily.service: Succeeded. Jun 22 05:19:12 volumio systemd[1]: Started Daily apt download activities. Jun 22 05:19:12 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jun 22 05:19:15 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:15 volumio volumio[980]: info: ----- Volumio3 ---- Jun 22 05:19:15 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:15 volumio volumio[980]: info: ----- System startup ---- Jun 22 05:19:15 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:15 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 22 05:19:15 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jun 22 05:19:15 volumio systemd[1]: Startup finished in 24.554s (kernel) + 35.698s (userspace) = 1min 252ms. Jun 22 05:19:17 volumio volumio[980]: info: MYVOLUMIO Environment detected Jun 22 05:19:17 volumio volumio[980]: info: Plugin folders cleanup Jun 22 05:19:17 volumio volumio[980]: info: Scanning into folder /volumio/app/plugins/ Jun 22 05:19:17 volumio volumio[980]: info: Scanning category audio_interface Jun 22 05:19:17 volumio volumio[980]: info: Scanning category miscellanea Jun 22 05:19:17 volumio volumio[980]: info: Scanning category music_service Jun 22 05:19:17 volumio volumio[980]: info: Scanning category plugins.json Jun 22 05:19:17 volumio volumio[980]: info: Scanning category system_controller Jun 22 05:19:17 volumio volumio[980]: info: Scanning category user_interface Jun 22 05:19:17 volumio volumio[980]: info: Scanning into folder /data/plugins/ Jun 22 05:19:17 volumio volumio[980]: info: Scanning category music_service Jun 22 05:19:17 volumio volumio[980]: info: Scanning category system_controller Jun 22 05:19:17 volumio volumio[980]: info: Plugin folders cleanup completed Jun 22 05:19:17 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:17 volumio volumio[980]: info: ----- Core plugins startup ---- Jun 22 05:19:17 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:17 volumio volumio[980]: info: Loading plugins from folder /volumio/app/plugins/ Jun 22 05:19:17 volumio volumio[980]: info: Adding plugin upnp to MyMusic Plugins Jun 22 05:19:17 volumio volumio[980]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 22 05:19:17 volumio volumio[980]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 22 05:19:17 volumio volumio[980]: info: Loading plugins from folder /data/plugins/ Jun 22 05:19:17 volumio volumio[980]: info: Loading plugin "system"... Jun 22 05:19:17 volumio volumio[980]: info: Loading plugin "appearance"... Jun 22 05:19:17 volumio systemd[1]: systemd-fsckd.service: Succeeded. Jun 22 05:19:19 volumio volumio-remote-updater[451]: [2025-06-22 05:19:19] [connect] Successful connection Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "network"... Jun 22 05:19:20 volumio volumio[980]: info: Refreshing Cached IP Addresses Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "services"... Jun 22 05:19:20 volumio sudo[1078]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 22 05:19:20 volumio sudo[1078]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "alsa_controller"... Jun 22 05:19:20 volumio sudo[1078]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:20 volumio sudo[1080]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 22 05:19:20 volumio sudo[1080]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:20 volumio sudo[1080]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:20 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "wizard"... Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "volumio_command_line_client"... Jun 22 05:19:20 volumio volumio[980]: info: Plugin upnp is not enabled Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "my_music"... Jun 22 05:19:20 volumio volumio[980]: info: Loading plugin "mpd"... Jun 22 05:19:21 volumio volumio[980]: info: Creating MPD Configuration file Jun 22 05:19:21 volumio volumio[980]: info: Loading plugin "upnp_browser"... Jun 22 05:19:21 volumio sudo[1086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 22 05:19:21 volumio sudo[1086]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:21 volumio sudo[1086]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:21 volumio sudo[1088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 22 05:19:21 volumio sudo[1088]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:21 volumio systemd[1]: Stopping Music Player Daemon... Jun 22 05:19:22 volumio systemd[1]: mpd.service: Succeeded. Jun 22 05:19:22 volumio systemd[1]: Stopped Music Player Daemon. Jun 22 05:19:22 volumio systemd[1]: Starting Music Player Daemon... Jun 22 05:19:23 volumio volumio[980]: info: Loading plugin "networkfs"... Jun 22 05:19:23 volumio volumio[980]: info: Starting Udev Watcher for removable devices Jun 22 05:19:23 volumio sudo[1096]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Flori,password=Ni4kamamo,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.188.36/Elements/Music /mnt/NAS/Elements Jun 22 05:19:23 volumio sudo[1096]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:24 volumio kernel: FS-Cache: Netfs 'cifs' registered for caching Jun 22 05:19:24 volumio kernel: Key type cifs.spnego registered Jun 22 05:19:24 volumio kernel: Key type cifs.idmap registered Jun 22 05:19:24 volumio kernel: CIFS: Attempting to mount //192.168.188.36/Elements/Music Jun 22 05:19:24 volumio 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. Jun 22 05:19:24 volumio volumio[980]: info: Ignoring mount for partition: boot Jun 22 05:19:24 volumio volumio[980]: info: Ignoring mount for partition: volumio Jun 22 05:19:24 volumio volumio[980]: info: Ignoring mount for partition: volumio_data Jun 22 05:19:24 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 22 05:19:24 volumio volumio[980]: info: Loading plugin "alarm-clock"... Jun 22 05:19:25 volumio mpd[1093]: Jun 22 05:19 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "airplay_emulation"... Jun 22 05:19:25 volumio sudo[1096]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:25 volumio volumio[980]: info: Starting Shairport Sync Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "last_100"... Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "webradio"... Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "i2s_dacs"... Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "volumiodiscovery"... Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** For more information see Jun 22 05:19:25 volumio node[980]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 05:19:25 volumio volumio[980]: *** WARNING *** For more information see Jun 22 05:19:25 volumio node[980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 05:19:25 volumio node[980]: *** WARNING *** For more information see Jun 22 05:19:25 volumio node[980]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 22 05:19:25 volumio node[980]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 22 05:19:25 volumio node[980]: *** WARNING *** For more information see Jun 22 05:19:25 volumio volumio[980]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 22 05:19:25 volumio volumio[980]: info: Discovery: Started advertising with name: Volumio Jun 22 05:19:25 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 22 05:19:25 volumio volumio[980]: info: Loading plugin "spop"... Jun 22 05:19:25 volumio mpd[1093]: Jun 22 05:19 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jun 22 05:19:25 volumio mpd[1093]: Jun 22 05:19 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jun 22 05:19:25 volumio systemd[1]: Started Music Player Daemon. Jun 22 05:19:25 volumio sudo[1088]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:29 volumio volumio[980]: info: Loading plugin "autostart"... Jun 22 05:19:29 volumio volumio[980]: info: Applying required configuration parameters for plugin autostart Jun 22 05:19:29 volumio volumio[980]: info: AutoStart - onVolumioStart - read config.json Jun 22 05:19:29 volumio volumio[980]: info: Loading plugin "outputs"... Jun 22 05:19:29 volumio volumio[980]: info: Loading plugin "albumart"... Jun 22 05:19:30 volumio volumio[980]: info: Plugin example_plugin is not enabled Jun 22 05:19:30 volumio volumio[980]: info: Loading plugin "inputs"... Jun 22 05:19:30 volumio volumio[980]: info: Loading plugin "updater_comm"... Jun 22 05:19:30 volumio volumio[980]: info: Plugin mpdemulation is not enabled Jun 22 05:19:30 volumio volumio[980]: info: Loading plugin "rest_api"... Jun 22 05:19:30 volumio volumio[980]: info: Loading plugin "websocket"... Jun 22 05:19:30 volumio volumio[980]: info: Loading i18n strings for locale de Jun 22 05:19:30 volumio volumio[980]: Updating browse sources language Jun 22 05:19:30 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 05:19:30 volumio volumio[980]: Forking 3 albumart workers Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::initPlayerControls Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 05:19:31 volumio volumio[980]: Express server listening on port 3000 Jun 22 05:19:31 volumio volumio[980]: [Metrics] WebUI: 17s 934.98ms Jun 22 05:19:31 volumio volumio[980]: info: CoreStateMachine::resetVolumioState Jun 22 05:19:31 volumio volumio[980]: info: CoreStateMachine::getcurrentVolume Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::volumioRetrievevolume Jun 22 05:19:31 volumio volumio[980]: info: CoreStateMachine::pushState Jun 22 05:19:31 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 22 05:19:31 volumio volumio[980]: info: CoreCommandRouter::volumioPushState Jun 22 05:19:31 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Jun 22 05:19:31 volumio volumio[980]: info: MPD Permissions set Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::volumioGetState Jun 22 05:19:32 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:32 volumio volumio[980]: info: MPD running with PID1093 Jun 22 05:19:32 volumio volumio[980]: ,establishing connection Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: Reloading queue from file Jun 22 05:19:32 volumio volumio[980]: error: updateQueue error: null Jun 22 05:19:32 volumio volumio[980]: info: CoreStateMachine::setRepeat null single undefined Jun 22 05:19:32 volumio volumio[980]: info: CoreStateMachine::pushState Jun 22 05:19:32 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::volumioPushState Jun 22 05:19:32 volumio volumio[980]: info: CoreStateMachine::setRandom null Jun 22 05:19:32 volumio volumio[980]: info: CoreStateMachine::pushState Jun 22 05:19:32 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::volumioPushState Jun 22 05:19:32 volumio volumio[980]: info: Setting Device type: Raspberry PI Jun 22 05:19:32 volumio volumio[980]: info: Listing playlists Jun 22 05:19:32 volumio volumio[980]: info: Listing playlists Jun 22 05:19:32 volumio volumio[980]: info: Completed loading Core Plugins Jun 22 05:19:32 volumio volumio[980]: info: Preparing to generate the ALSA configuration file Jun 22 05:19:32 volumio volumio[980]: error: updateQueue error: null Jun 22 05:19:32 volumio volumio[980]: info: Asound.conf file unchanged, so no further update is needed Jun 22 05:19:32 volumio volumio[980]: info: Output device has changed, restarting MPD Jun 22 05:19:32 volumio volumio[980]: info: Output device has changed, restarting Shairport Sync Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:32 volumio sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 22 05:19:32 volumio sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:32 volumio sudo[1174]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:32 volumio sudo[1175]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 22 05:19:32 volumio sudo[1175]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:32 volumio volumio[980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 05:19:32 volumio volumio[980]: info: ___________ START PLUGINS ___________ Jun 22 05:19:32 volumio volumio[980]: Starting albumart workers Jun 22 05:19:32 volumio volumio[980]: Starting albumart workers Jun 22 05:19:32 volumio volumio[980]: Starting albumart workers Jun 22 05:19:32 volumio systemd[1]: Stopping Music Player Daemon... Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 05:19:32 volumio volumio[980]: info: [1750569572931] CoreMusicLibrary::Adding element Media Servers Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:32 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:33 volumio systemd[1]: mpd.service: Succeeded. Jun 22 05:19:33 volumio systemd[1]: Stopped Music Player Daemon. Jun 22 05:19:33 volumio systemd[1]: Starting Music Player Daemon... Jun 22 05:19:33 volumio volumio[980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:33 volumio volumio[980]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 05:19:33 volumio volumio[980]: info: [1750569573397] CoreMusicLibrary::Adding element Last_100 Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 05:19:33 volumio volumio[980]: info: [1750569573424] CoreMusicLibrary::Adding element Webradio Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 05:19:33 volumio volumio[980]: info: Creating Spotify config file Jun 22 05:19:33 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:33 volumio volumio[980]: info: AutoStart - onStart Jun 22 05:19:33 volumio volumio[980]: info: Volumio Calling Home Jun 22 05:19:33 volumio volumio[980]: info: Completed starting Core Plugins Jun 22 05:19:33 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:33 volumio volumio[980]: info: ----- MyVolumio plugins startup ---- Jun 22 05:19:33 volumio volumio[980]: info: ------------------------------------------- Jun 22 05:19:33 volumio volumio[980]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 22 05:19:34 volumio volumio[980]: info: Discovery: adding df3e3103-3aa6-4b22-971c-d42e9128292d Jun 22 05:19:34 volumio volumio[980]: info: Discovery: Found device Volumio Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::volumioGetState Jun 22 05:19:34 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:34 volumio volumio[980]: info: Discovery: this is already registered, df3e3103-3aa6-4b22-971c-d42e9128292d Jun 22 05:19:34 volumio volumio[980]: info: Discovery: Found device Volumio Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::volumioGetState Jun 22 05:19:34 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:34 volumio volumio[980]: info: MPD Permissions set Jun 22 05:19:34 volumio volumio[980]: info: Volumio called home Jun 22 05:19:34 volumio volumio[980]: info: Spotify config file written Jun 22 05:19:34 volumio volumio-remote-updater[451]: [2025-06-22 05:19:34] [connect] Successful connection Jun 22 05:19:34 volumio sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 22 05:19:34 volumio sudo[1218]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:34 volumio volumio[980]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio systemd[1]: Started go-librespot Daemon. Jun 22 05:19:34 volumio sudo[1218]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:34 volumio go-librespot[1224]: go-librespot daemon starting... Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 05:19:34 volumio volumio[980]: info: No need to fix Spotify hosts Jun 22 05:19:35 volumio volumio-remote-updater[451]: [2025-06-22 05:19:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1750569574 101 Jun 22 05:19:35 volumio volumio[980]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2 Jun 22 05:19:35 volumio volumio[980]: info: Starting Shairport Sync Jun 22 05:19:35 volumio volumio[980]: info: Starting Shairport Sync Jun 22 05:19:35 volumio volumio[980]: info: Starting Shairport Sync Jun 22 05:19:35 volumio sudo[1232]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 05:19:35 volumio sudo[1232]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:35 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 22 05:19:35 volumio systemd[1]: shairport-sync.service: Succeeded. Jun 22 05:19:35 volumio go-librespot[1224]: time="2025-06-22T05:19:35Z" level=info msg="running go-librespot 0.2.0" Jun 22 05:19:35 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 22 05:19:35 volumio go-librespot[1224]: time="2025-06-22T05:19:35Z" level=debug msg="app state loaded" Jun 22 05:19:35 volumio go-librespot[1224]: time="2025-06-22T05:19:35Z" level=debug msg="stored credentials not found" Jun 22 05:19:35 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 22 05:19:35 volumio go-librespot[1224]: time="2025-06-22T05:19:35Z" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 05:19:35 volumio sudo[1232]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:35 volumio sudo[1237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 05:19:35 volumio sudo[1237]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:35 volumio sudo[1234]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 22 05:19:35 volumio sudo[1234]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:35 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 22 05:19:35 volumio systemd[1]: shairport-sync.service: Succeeded. Jun 22 05:19:35 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 22 05:19:35 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 22 05:19:35 volumio sudo[1237]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:35 volumio sudo[1234]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:35 volumio volumio[980]: info: Shairport-Sync Started Jun 22 05:19:35 volumio volumio[980]: Error adding Membership: Error: addMembership EINVAL Jun 22 05:19:35 volumio volumio[980]: info: Shairport-Sync Started Jun 22 05:19:35 volumio volumio[980]: info: Shairport-Sync Started Jun 22 05:19:35 volumio volumio[980]: info: CoreCommandRouter::volumioGetState Jun 22 05:19:35 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:36 volumio mpd[1189]: Jun 22 05:19 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 22 05:19:36 volumio go-librespot[1224]: time="2025-06-22T05:19:36Z" 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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 22 05:19:36 volumio go-librespot[1224]: time="2025-06-22T05:19:36Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jun 22 05:19:36 volumio go-librespot[1224]: time="2025-06-22T05:19:36Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jun 22 05:19:36 volumio go-librespot[1224]: time="2025-06-22T05:19:36Z" level=info msg="zeroconf server listening on port 45841" Jun 22 05:19:36 volumio mpd[1189]: Jun 22 05:19 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jun 22 05:19:36 volumio mpd[1189]: Jun 22 05:19 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jun 22 05:19:36 volumio systemd[1]: Started Music Player Daemon. Jun 22 05:19:36 volumio sudo[1175]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:36 volumio volumio[980]: error: updateQueue error: null Jun 22 05:19:38 volumio volumio[980]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 22 05:19:38 volumio volumio[980]: info: go-librespot daemon successfully initialized Jun 22 05:19:41 volumio volumio[980]: info: Initializing connection to go-librespot Websocket Jun 22 05:19:44 volumio go-librespot[1224]: time="2025-06-22T05:19:44Z" level=debug msg="new websocket client" Jun 22 05:19:44 volumio volumio[980]: info: Connection to go-librespot Websocket established Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin bluetooth to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin multiroom to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin metavolumio to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin cd_controller to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 22 05:19:45 volumio volumio[980]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 22 05:19:47 volumio volumio[980]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 22 05:19:47 volumio volumio[980]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 22 05:19:47 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:47 volumio volumio[980]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 22 05:19:47 volumio volumio[980]: info: Starting MyVolumio Remote Streaming Endpoints Jun 22 05:19:47 volumio volumio[980]: info: MyVolumio login type: Token Jun 22 05:19:48 volumio volumio[980]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 22 05:19:48 volumio volumio[980]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 22 05:19:48 volumio go-librespot[1224]: time="2025-06-22T05:19:48Z" level=debug msg="obtained new client token: AAD2a1bIoAqhX8ZNS1sY8+7U/AOrWzKDp5gRLVSE4wp4/ICXt81nkp1XNWL/3KmcE1s9Voc4bMPuNEda6M5iuREYhhBIoagN02gMc8fqP3Z5o65fp0lRW6Ren8dr5C1gvLiw082TinumF0g7UH2tKMNAculkS0itP6MNi0AP9mGULutAUqvq83TUnMGR72e0Q3jRQPdobqFaX+C2eDogDivw1ulE3mnXupXulxwYCxnb0CaAaz1HN5g0bms=" Jun 22 05:19:48 volumio go-librespot[1224]: time="2025-06-22T05:19:48Z" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="completed keyexchange" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="completed challenge" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=info msg="authenticated AP as zeabei05c79v8k4xxcodi2tpv" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=info msg="authenticated Login5 as zeabei05c79v8k4xxcodi2tpv" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=info msg="accepted zeroconf user zeabei05c79v8k4xxcodi2tpv from Xiaomi 13T Pro" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="dealer connection opened" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=trace msg="starting accesspoint recv loop" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=trace msg="starting dealer recv loop" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=trace msg="received accesspoint ping" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="received connection id: ODYxYTk1ZTYtMTk0Mi00OTBlLWFjZGMtOGQ1NmM5ZDVlODY5K2RlYWxlcit0Y3A6Ly8wYWNhNTg4Yi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMEVDRTdEMjY5QjY2OEY5RkFFMDMxODZENDE1MUM0MTFBOTRDRUQ2MUY1NTI2Nzc1RjA2RTJFQzBEMjhDMkY2Qw==" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="put connect state because NEW_DEVICE" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="update volume to 65535/65535" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=trace msg="received accesspoint pong ack" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="handling transfer player command from 66615fb7bce39246e1faf2fa274739519a2a983c" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO3fcDiH" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=trace msg="fetched new page 0 with 38 items (list: 38)" uri="spotify:playlist:37i9dQZF1DZ06evO3fcDiH" Jun 22 05:19:49 volumio go-librespot[1224]: time="2025-06-22T05:19:49Z" level=debug msg="loading track (paused: true, position: 268341ms)" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=trace msg="emitting websocket event: will_play" Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="selected format OGG_VORBIS_320 (7eda5600ed9909afe1971e2aa6372fe6cdee3e18)" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="requested aes key for file 7eda5600ed9909afe1971e2aa6372fe6cdee3e18, gid: 5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:50 volumio volumio[980]: info: Starting Streaming Service Transparent Proxy Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="fetched first chunk of 21, total size is 10817114 bytes" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:50 volumio volumio[980]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 22 05:19:50 volumio volumio[980]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 22 05:19:50 volumio volumio[980]: info: Streaming services startup Jun 22 05:19:50 volumio volumio[980]: info: Starting Streaming Daemon Jun 22 05:19:50 volumio sudo[1252]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 22 05:19:50 volumio sudo[1252]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 05:19:50 volumio sudo[1252]: pam_unix(sudo:session): session closed for user root Jun 22 05:19:50 volumio volumio[980]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 22 05:19:50 volumio go-librespot[1224]: time="2025-06-22T05:19:50Z" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="fetched chunk 20/20, size: 331354" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="fetched chunk 19/20, size: 524288" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="seek to 268341ms (diff: 141ms, samples: 11833838, bytes: 10382388)" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="created new output device" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=info msg="loaded track \"Mit Dir\" (paused: true, position: 268341ms, duration: 278960ms, prefetched: false)" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="emitting websocket event: metadata" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="emitting websocket event: active" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="sending successful reply for dealer request" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 22 05:19:51 volumio volumio[980]: info: Getting Spotify volume Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="emitting websocket event: paused" Jun 22 05:19:51 volumio volumio[980]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5EX0HiIyvhavnpjgbwDCeL","play_origin":"voice-assistant-alexa"}} Jun 22 05:19:51 volumio volumio[980]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5EX0HiIyvhavnpjgbwDCeL","name":"Mit Dir","artist_names":["Freundeskreis","Joy Denalane","Max Herre","Don Philippe","DJ Friction"],"album_name":"Esperanto","album_cover_url":"https://i.scdn.co/image/ab67616d00001e028ffff9558c3bd4f642446cf4","position":268341,"duration":278960,"release_date":"year:1999 month:4 day:21","track_number":11,"disc_number":1}} Jun 22 05:19:51 volumio volumio[980]: SPOTIFY: received: {"type":"active","data":null} Jun 22 05:19:51 volumio volumio[980]: info: Aligning Spotify Volume to Volumio Volume Jun 22 05:19:51 volumio volumio[980]: info: CoreCommandRouter::volumioGetState Jun 22 05:19:51 volumio volumio[980]: info: CorePlayQueue::getTrack 0 Jun 22 05:19:51 volumio volumio[980]: error: Cannot start Volumio Streaming Daemon Jun 22 05:19:51 volumio volumio[980]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 22 05:19:51 volumio volumio[980]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 22 05:19:51 volumio volumio[980]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5EX0HiIyvhavnpjgbwDCeL","play_origin":"voice-assistant-alexa"}} Jun 22 05:19:51 volumio volumio[980]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because VOLUME_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="emitting websocket event: volume" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="handling update_context player command from 66615fb7bce39246e1faf2fa274739519a2a983c" Jun 22 05:19:51 volumio volumio[980]: TypeError: Cannot read property 'service' of undefined Jun 22 05:19:51 volumio volumio[980]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Jun 22 05:19:51 volumio volumio[980]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Jun 22 05:19:51 volumio volumio[980]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Jun 22 05:19:51 volumio volumio[980]: at WebSocket.emit (events.js:315:20) Jun 22 05:19:51 volumio volumio[980]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 22 05:19:51 volumio volumio[980]: at Receiver.emit (events.js:315:20) Jun 22 05:19:51 volumio volumio[980]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 22 05:19:51 volumio volumio[980]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 22 05:19:51 volumio volumio[980]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 22 05:19:51 volumio volumio[980]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 22 05:19:51 volumio volumio[980]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 22 05:19:51 volumio volumio[980]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 22 05:19:51 volumio volumio[980]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 22 05:19:51 volumio volumio[980]: at Socket.emit (events.js:315:20) Jun 22 05:19:51 volumio volumio[980]: at addChunk (internal/streams/readable.js:309:12) Jun 22 05:19:51 volumio volumio[980]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 22 05:19:51 volumio volumio[980]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="sending successful reply for dealer request" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="handling update_context player command from 66615fb7bce39246e1faf2fa274739519a2a983c" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="sending successful reply for dealer request" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="handling resume player command from 66615fb7bce39246e1faf2fa274739519a2a983c" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=trace msg="seek to 268341ms (diff: 141ms, samples: 11833838, bytes: 10382388)" uri="spotify:track:5EX0HiIyvhavnpjgbwDCeL" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="resume track at 268247ms" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="sending successful reply for dealer request" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="prefetching next track" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="selected format OGG_VORBIS_320 (b8b5f74f89f44c0d7d4010ec43826422f13f719a)" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:51 volumio go-librespot[1224]: time="2025-06-22T05:19:51Z" level=debug msg="requested aes key for file b8b5f74f89f44c0d7d4010ec43826422f13f719a, gid: 32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=trace msg="emitting websocket event: playing" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=debug msg="fetched first chunk of 13, total size is 6706390 bytes" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=info msg="prefetched track \"Skyline\" (duration: 154226ms)" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio go-librespot[1224]: time="2025-06-22T05:19:52Z" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:32Za48jJCRUE7YpVC07EBn" Jun 22 05:19:52 volumio sudo[1273]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-22 05:18 Jun 22 05:19:52 volumio sudo[1273]: 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="b1c3cf61c2a0027c66bab1eb0a3795f80c1f2e95" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e3eb3ee5b16063502f3a1735e11a28cfe54a0f46" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 25 Jun 2023 07:20:58 PM CEST" VOLUMIO_VERSION="3.512" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="946a42b62509f37b5e7e2d86a2932a62"