-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-02-16 19:03:14 CET. -- Feb 16 19:02:48 volumio3 systemd-timedated[904]: Changed local time to Sun Feb 16 19:02:48 2025 Feb 16 19:02:48 volumio3 sudo[902]: pam_unix(sudo:session): session closed for user root Feb 16 19:02:48 volumio3 volumio-time-update[590]: volumio-time-update-util: System time updated successfully. Feb 16 19:02:48 volumio3 systemd[1]: Starting Daily apt download activities... Feb 16 19:02:48 volumio3 systemd[1]: Started Volumio Time Update Utility. Feb 16 19:02:48 volumio3 systemd[1]: Reached target Multi-User System. Feb 16 19:02:48 volumio3 systemd[1]: Reached target Graphical Interface. Feb 16 19:02:48 volumio3 systemd[1]: Started Run on boot service by wd. Feb 16 19:02:48 volumio3 systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 16 19:02:48 volumio3 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 16 19:02:48 volumio3 systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 16 19:02:49 volumio3 volumio[805]: info: MYVOLUMIO Environment detected Feb 16 19:02:49 volumio3 nmbd[712]: [2025/02/16 19:02:49.776412, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Feb 16 19:02:49 volumio3 nmbd[712]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.99.24 for name WORKGROUP<1d>. Feb 16 19:02:49 volumio3 nmbd[712]: This response was from IP 192.168.99.20, reporting an IP address of 192.168.99.20. Feb 16 19:02:50 volumio3 volumio[805]: info: Plugin folders cleanup Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning into folder /volumio/app/plugins/ Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category audio_interface Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category miscellanea Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category music_service Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category plugins.json Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category system_controller Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category user_interface Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning into folder /data/plugins/ Feb 16 19:02:50 volumio3 volumio[805]: info: Scanning category music_service Feb 16 19:02:50 volumio3 volumio[805]: info: Plugin folders cleanup completed Feb 16 19:02:50 volumio3 volumio[805]: info: ------------------------------------------- Feb 16 19:02:50 volumio3 volumio[805]: info: ----- Core plugins startup ---- Feb 16 19:02:50 volumio3 volumio[805]: info: ------------------------------------------- Feb 16 19:02:50 volumio3 volumio[805]: info: Loading plugins from folder /volumio/app/plugins/ Feb 16 19:02:50 volumio3 volumio[805]: info: Adding plugin upnp to MyMusic Plugins Feb 16 19:02:50 volumio3 volumio[805]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 16 19:02:50 volumio3 volumio[805]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 16 19:02:50 volumio3 volumio[805]: info: Loading plugins from folder /data/plugins/ Feb 16 19:02:50 volumio3 volumio[805]: info: Loading plugin "system"... Feb 16 19:02:50 volumio3 volumio[805]: info: Loading plugin "appearance"... Feb 16 19:02:53 volumio3 systemd[1]: apt-daily.service: Succeeded. Feb 16 19:02:53 volumio3 systemd[1]: Started Daily apt download activities. Feb 16 19:02:53 volumio3 systemd[1]: Startup finished in 16.031s (kernel) + 28.052s (userspace) = 44.084s. Feb 16 19:02:53 volumio3 volumio[805]: info: Loading plugin "network"... Feb 16 19:02:53 volumio3 volumio[805]: info: Refreshing Cached IP Addresses Feb 16 19:02:53 volumio3 sudo[963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 16 19:02:53 volumio3 sudo[963]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:02:53 volumio3 sudo[963]: pam_unix(sudo:session): session closed for user root Feb 16 19:02:53 volumio3 volumio[805]: info: Loading plugin "services"... Feb 16 19:02:53 volumio3 sudo[965]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 16 19:02:53 volumio3 sudo[965]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:02:53 volumio3 volumio[805]: info: Loading plugin "alsa_controller"... Feb 16 19:02:53 volumio3 sudo[965]: pam_unix(sudo:session): session closed for user root Feb 16 19:02:54 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "wizard"... Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "networkfs"... Feb 16 19:02:54 volumio3 volumio[805]: info: Starting Udev Watcher for removable devices Feb 16 19:02:54 volumio3 sudo[990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=js3gr40,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.99.31/bu/music /mnt/NAS/rpi4-2 Feb 16 19:02:54 volumio3 sudo[990]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:02:54 volumio3 volumio[805]: info: Ignoring mount for partition: boot Feb 16 19:02:54 volumio3 volumio[805]: info: Ignoring mount for partition: volumio Feb 16 19:02:54 volumio3 volumio[805]: info: Ignoring mount for partition: volumio_data Feb 16 19:02:54 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "volumio_command_line_client"... Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "upnp"... Feb 16 19:02:54 volumio3 volumio[805]: info: [1739728974343] Starting Upmpd Daemon Feb 16 19:02:54 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "my_music"... Feb 16 19:02:54 volumio3 volumio[805]: info: Loading plugin "mpd"... Feb 16 19:02:54 volumio3 kernel: Key type cifs.spnego registered Feb 16 19:02:54 volumio3 kernel: Key type cifs.idmap registered Feb 16 19:02:54 volumio3 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. Feb 16 19:02:54 volumio3 kernel: CIFS: Attempting to mount //192.168.99.31/bu/music Feb 16 19:02:55 volumio3 volumio[805]: info: Loading plugin "upnp_browser"... Feb 16 19:02:56 volumio3 volumio[805]: info: Loading plugin "alarm-clock"... Feb 16 19:02:56 volumio3 volumio[805]: info: Loading plugin "airplay_emulation"... Feb 16 19:02:56 volumio3 volumio[805]: info: Starting Shairport Sync Feb 16 19:02:56 volumio3 volumio[805]: info: Loading plugin "last_100"... Feb 16 19:02:56 volumio3 volumio[805]: info: Loading plugin "webradio"... Feb 16 19:02:56 volumio3 kernel: cryptd: max_cpu_qlen set to 1000 Feb 16 19:02:57 volumio3 volumio[805]: info: Loading plugin "i2s_dacs"... Feb 16 19:02:57 volumio3 volumio[805]: info: Loading plugin "volumiodiscovery"... Feb 16 19:02:57 volumio3 sudo[990]: pam_unix(sudo:session): session closed for user root Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** For more information see Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 16 19:02:57 volumio3 volumio[805]: *** WARNING *** For more information see Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** For more information see Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 16 19:02:57 volumio3 node[805]: *** WARNING *** For more information see Feb 16 19:02:57 volumio3 volumio[805]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 16 19:02:57 volumio3 volumio[805]: info: Discovery: Started advertising with name: Volumio3 Feb 16 19:02:57 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 16 19:02:57 volumio3 volumio[805]: info: Loading plugin "spop"... Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "outputs"... Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "albumart"... Feb 16 19:03:00 volumio3 volumio[805]: info: Plugin example_plugin is not enabled Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "inputs"... Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "updater_comm"... Feb 16 19:03:00 volumio3 volumio[805]: info: Plugin mpdemulation is not enabled Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "rest_api"... Feb 16 19:03:00 volumio3 volumio[805]: info: Loading plugin "websocket"... Feb 16 19:03:00 volumio3 volumio[805]: info: Starting Socket.io Server version 2.3.0 Feb 16 19:03:00 volumio3 volumio[805]: info: Loading i18n strings for locale en Feb 16 19:03:00 volumio3 volumio[805]: Updating browse sources language Feb 16 19:03:00 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 19:03:01 volumio3 systemd[1]: systemd-fsckd.service: Succeeded. Feb 16 19:03:01 volumio3 volumio[805]: Forking 3 albumart workers Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::initPlayerControls Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 16 19:03:01 volumio3 volumio[805]: Express server listening on port 3000 Feb 16 19:03:01 volumio3 volumio[805]: [Metrics] WebUI: 16s 403.84ms Feb 16 19:03:01 volumio3 volumio[805]: info: CoreStateMachine::resetVolumioState Feb 16 19:03:01 volumio3 volumio[805]: info: CoreStateMachine::getcurrentVolume Feb 16 19:03:01 volumio3 volumio[805]: info: CoreCommandRouter::volumioRetrievevolume Feb 16 19:03:01 volumio3 volumio[805]: info: Volumio Network Manager: Network status updated: 1 Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:02 volumio3 volumio[805]: info: Setting Device type: Raspberry PI Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::setRepeat false single undefined Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::pushState Feb 16 19:03:02 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::volumioPushState Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::setRandom true Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::pushState Feb 16 19:03:02 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::volumioPushState Feb 16 19:03:02 volumio3 volumio[805]: info: Completed loading Core Plugins Feb 16 19:03:02 volumio3 volumio[805]: info: Preparing to generate the ALSA configuration file Feb 16 19:03:02 volumio3 volumio[805]: info: VolumeController:: Volume=100 Mute =false Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::pushState Feb 16 19:03:02 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::volumioPushState Feb 16 19:03:02 volumio3 volumio[805]: info: CoreStateMachine::updateTrackBlock Feb 16 19:03:02 volumio3 volumio[805]: info: CorePlayQueue::getTrackBlock Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::volumioRetrievevolume Feb 16 19:03:02 volumio3 volumio[805]: info: Reloading queue from file Feb 16 19:03:02 volumio3 volumio[805]: info: Asound.conf file unchanged, so no further update is needed Feb 16 19:03:02 volumio3 volumio[805]: info: Output device has changed, restarting MPD Feb 16 19:03:02 volumio3 volumio-remote-updater[569]: [2025-02-16 19:03:02] [connect] Successful connection Feb 16 19:03:02 volumio3 volumio[805]: info: Output device has changed, restarting Shairport Sync Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:02 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:02 volumio3 sudo[1072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 16 19:03:02 volumio3 sudo[1074]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 16 19:03:02 volumio3 sudo[1074]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:02 volumio3 sudo[1072]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:03 volumio3 sudo[1072]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:03 volumio3 systemd[1]: Stopping Music Player Daemon... Feb 16 19:03:03 volumio3 volumio[805]: Starting albumart workers Feb 16 19:03:03 volumio3 volumio[805]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 19:03:03 volumio3 volumio[805]: info: ___________ START PLUGINS ___________ Feb 16 19:03:03 volumio3 volumio[805]: Starting albumart workers Feb 16 19:03:03 volumio3 volumio[805]: Starting albumart workers Feb 16 19:03:03 volumio3 volumio[805]: info: ControllerMpd::onStart: Initializing MPD Feb 16 19:03:03 volumio3 volumio[805]: info: Creating MPD Configuration file Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 19:03:03 volumio3 volumio[805]: info: [1739728983313] CoreMusicLibrary::Adding element Media Servers Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 19:03:03 volumio3 sudo[1081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 16 19:03:03 volumio3 systemd[1]: mpd.service: Succeeded. Feb 16 19:03:03 volumio3 systemd[1]: Stopped Music Player Daemon. Feb 16 19:03:03 volumio3 sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:03 volumio3 sudo[1083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 16 19:03:03 volumio3 sudo[1083]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:03 volumio3 sudo[1081]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:03 volumio3 systemd[1]: Starting Music Player Daemon... Feb 16 19:03:03 volumio3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Feb 16 19:03:03 volumio3 systemd[1]: mpd.service: Succeeded. Feb 16 19:03:03 volumio3 systemd[1]: Stopped Music Player Daemon. Feb 16 19:03:03 volumio3 systemd[1]: Starting Music Player Daemon... Feb 16 19:03:03 volumio3 volumio[805]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:03 volumio3 sudo[1090]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 16 19:03:03 volumio3 sudo[1090]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:03 volumio3 volumio[805]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 19:03:03 volumio3 sudo[1090]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 19:03:03 volumio3 volumio[805]: info: [1739728983828] CoreMusicLibrary::Adding element Last_100 Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 19:03:03 volumio3 volumio[805]: info: [1739728983838] CoreMusicLibrary::Adding element Webradio Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 19:03:03 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 19:03:03 volumio3 volumio[805]: info: Initializing BBC Radios Feb 16 19:03:04 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 19:03:04 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:04 volumio3 volumio[805]: info: Creating Spotify config file Feb 16 19:03:04 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:04 volumio3 volumio[805]: info: Volumio Calling Home Feb 16 19:03:05 volumio3 volumio[805]: info: Discovery: adding d42e7524-9646-4121-adf5-eb9b6d28e6a7 Feb 16 19:03:05 volumio3 volumio[805]: info: Discovery: Found device Volumio3 Feb 16 19:03:05 volumio3 sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::volumioGetState Feb 16 19:03:05 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:05 volumio3 sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:05 volumio3 sudo[1150]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:05 volumio3 volumio[805]: info: MPD Permissions set Feb 16 19:03:05 volumio3 volumio[805]: info: MPD Permissions set Feb 16 19:03:05 volumio3 volumio[805]: info: VolumeController:: Volume=100 Mute =false Feb 16 19:03:05 volumio3 volumio[805]: info: CoreStateMachine::pushState Feb 16 19:03:05 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::volumioPushState Feb 16 19:03:05 volumio3 sudo[1152]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 16 19:03:05 volumio3 sudo[1152]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:05 volumio3 sudo[1152]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:05 volumio3 volumio-remote-updater[569]: [2025-02-16 19:03:05] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1739728982 101 Feb 16 19:03:05 volumio3 volumio[805]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Feb 16 19:03:05 volumio3 volumio[805]: info: Volumio called home Feb 16 19:03:05 volumio3 volumio[805]: info: Spotify config file written Feb 16 19:03:05 volumio3 sudo[1156]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 16 19:03:05 volumio3 sudo[1156]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:05 volumio3 volumio[805]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 systemd[1]: Started go-librespot Daemon. Feb 16 19:03:05 volumio3 go-librespot[1158]: Librespot-go daemon starting... Feb 16 19:03:05 volumio3 sudo[1156]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 19:03:05 volumio3 volumio[805]: info: Starting Shairport Sync Feb 16 19:03:05 volumio3 volumio[805]: info: Starting Shairport Sync Feb 16 19:03:05 volumio3 volumio[805]: info: Starting Shairport Sync Feb 16 19:03:05 volumio3 sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 19:03:05 volumio3 sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:05 volumio3 sudo[1176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 19:03:05 volumio3 sudo[1176]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:06 volumio3 sudo[1179]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 19:03:06 volumio3 sudo[1179]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:06 volumio3 volumio[805]: info: CoreCommandRouter::volumioGetState Feb 16 19:03:06 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=info msg="generated new device id: 046bee102d0f2eedbce89cdd9cb4d1f5b8cfb9eb" Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=debug msg="stored credentials found for xa60m3puti317444kkwsgrlme" Feb 16 19:03:06 volumio3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 16 19:03:06 volumio3 systemd[1]: shairport-sync.service: Succeeded. Feb 16 19:03:06 volumio3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 16 19:03:06 volumio3 sudo[1183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 16 19:03:06 volumio3 sudo[1183]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:06 volumio3 volumio[805]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 16 19:03:06 volumio3 volumio[805]: SPOTIFY: BQApX8e0tJelFee3BVZnsNBtFKvvC8_W7uF0hYtTO1HfV9EQy3EL_407i6wdkBxiSdKxqiAasb1OuIeqwwd_KZFxtmn3_X9XM-LlaXtMhgJx2QW3Ds2ocKyGq3iwdH_ORT6CTAOmK6NVTcNimXq0AN8HlZGHo2PQrkPp1TMj4mt2JKbZYocGzUR62mKie4lMzj57OPxTLVOnByfiIy5wyyt7KFyTdHuwUsiSJECDrOufDQVs31D_WDoMtEa6rQvccPRxBNIzLlSk7dGqeJG6cd244Ezr7nD92A4av9A Feb 16 19:03:06 volumio3 volumio[805]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 16 19:03:06 volumio3 volumio[805]: info: New Spotify access token = BQApX8e0tJelFee3BVZnsNBtFKvvC8_W7uF0hYtTO1HfV9EQy3EL_407i6wdkBxiSdKxqiAasb1OuIeqwwd_KZFxtmn3_X9XM-LlaXtMhgJx2QW3Ds2ocKyGq3iwdH_ORT6CTAOmK6NVTcNimXq0AN8HlZGHo2PQrkPp1TMj4mt2JKbZYocGzUR62mKie4lMzj57OPxTLVOnByfiIy5wyyt7KFyTdHuwUsiSJECDrOufDQVs31D_WDoMtEa6rQvccPRxBNIzLlSk7dGqeJG6cd244Ezr7nD92A4av9A Feb 16 19:03:06 volumio3 volumio[805]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 16 19:03:06 volumio3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 16 19:03:06 volumio3 sudo[1174]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 sudo[1176]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 sudo[1179]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 systemd[1]: Started UPnP Renderer front-end to MPD. Feb 16 19:03:06 volumio3 systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 16 19:03:06 volumio3 systemd[1]: mpd.service: Failed with result 'protocol'. Feb 16 19:03:06 volumio3 volumio[805]: info: Shairport-Sync Started Feb 16 19:03:06 volumio3 sudo[1183]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 volumio[805]: Error adding Membership: Error: addMembership EINVAL Feb 16 19:03:06 volumio3 volumio[805]: info: Shairport-Sync Started Feb 16 19:03:06 volumio3 systemd[1]: Failed to start Music Player Daemon. Feb 16 19:03:06 volumio3 volumio[805]: info: Shairport-Sync Started Feb 16 19:03:06 volumio3 volumio[805]: info: Upmpdcli Daemon Started Feb 16 19:03:06 volumio3 sudo[1074]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 sudo[1083]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 volumio[805]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 16 19:03:06 volumio3 volumio[805]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 16 19:03:06 volumio3 volumio[805]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 16 19:03:06 volumio3 volumio[805]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 16 19:03:06 volumio3 volumio[805]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 16 19:03:06 volumio3 volumio[805]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 16 19:03:06 volumio3 volumio[805]: info: Completed starting Core Plugins Feb 16 19:03:06 volumio3 volumio[805]: info: ------------------------------------------- Feb 16 19:03:06 volumio3 volumio[805]: info: ----- MyVolumio plugins startup ---- Feb 16 19:03:06 volumio3 volumio[805]: info: ------------------------------------------- Feb 16 19:03:06 volumio3 volumio[805]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 16 19:03:06 volumio3 systemd[1]: Starting Music Player Daemon... Feb 16 19:03:06 volumio3 sudo[1192]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 16 19:03:06 volumio3 sudo[1192]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 19:03:06 volumio3 sudo[1192]: pam_unix(sudo:session): session closed for user root Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 16 19:03:06 volumio3 go-librespot[1158]: time="2025-02-16T19:03:06+01:00" level=debug msg="zeroconf server listening on port 36959" Feb 16 19:03:06 volumio3 volumio[805]: SPOTIFY: User informations: {"country":"BE","display_name":"Ward.dewerchin","email":"ward.dewerchin@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/xa60m3puti317444kkwsgrlme"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/xa60m3puti317444kkwsgrlme","id":"xa60m3puti317444kkwsgrlme","images":[],"product":"premium","type":"user","uri":"spotify:user:xa60m3puti317444kkwsgrlme"} Feb 16 19:03:06 volumio3 volumio[805]: info: Spotify Successfully logged in Feb 16 19:03:06 volumio3 volumio[805]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 19:03:06 volumio3 volumio[805]: info: [1739728986931] CoreMusicLibrary::Adding element Spotify Feb 16 19:03:06 volumio3 volumio[805]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 19:03:06 volumio3 volumio[805]: Cannot find translation for source Spotify Feb 16 19:03:07 volumio3 go-librespot[1158]: time="2025-02-16T19:03:07+01:00" level=debug msg="obtained new client token: AAD9ZmOPPDspdM+b/jlk+pBxXwPwS3SEAeUusaGn2LRx2WgTV7Fx02jO+KiE5XpmBRltM7hwyVOrdVh0yCLWRjb923+9JUoyMd3t/tlvqkVqSt84+l+RXBzNuqwuMalOWzSH5Z5TnKF+clW4URjUNUHETUaWYFP62bcdp7Wi29MEzwVnovsSHqrb48iTGV50vCzZaa8JILrgV4UdBV1uqd3CNu3Bh2eauQA+90NyMZ1xXR3pDyS3jovmdvU=" Feb 16 19:03:07 volumio3 go-librespot[1158]: time="2025-02-16T19:03:07+01:00" level=debug msg="completed keyexchange" Feb 16 19:03:07 volumio3 systemd[1]: systemd-hostnamed.service: Succeeded. Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="completed challenge" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="dealer connection opened" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="initializing zeroconf session, username: xa60m3puti317444kkwsgrlme" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="autoplay enabled: false" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 16 19:03:08 volumio3 go-librespot[1158]: time="2025-02-16T19:03:08+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 16 19:03:08 volumio3 volumio[805]: info: go-librespot daemon successfully initialized Feb 16 19:03:09 volumio3 mpd[1196]: Feb 16 19:03 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 16 19:03:09 volumio3 go-librespot[1158]: time="2025-02-16T19:03:09+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 16 19:03:09 volumio3 systemd[1]: Started Music Player Daemon. Feb 16 19:03:09 volumio3 volumio[805]: Upnp client error: Error: This socket has been ended by the other party Feb 16 19:03:09 volumio3 mpd_monitor.sh[563]: MPD restarted due to no mpc output. Feb 16 19:03:10 volumio3 volumio[805]: error: MPD error: The expression evaluated to a falsy value: Feb 16 19:03:10 volumio3 volumio[805]: assert.ok(self.idling) Feb 16 19:03:10 volumio3 volumio[805]: error: The expression evaluated to a falsy value: Feb 16 19:03:10 volumio3 volumio[805]: assert.ok(self.idling) Feb 16 19:03:10 volumio3 volumio[805]: error: updateQueue error: null Feb 16 19:03:10 volumio3 volumio[1187]: Generating RSA private key, 4096 bit long modulus (2 primes) Feb 16 19:03:10 volumio3 go-librespot[1158]: time="2025-02-16T19:03:10+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Feb 16 19:03:10 volumio3 go-librespot[1158]: time="2025-02-16T19:03:10+01:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.99.24:45806->34.158.1.133:4070: use of closed network connection" Feb 16 19:03:10 volumio3 go-librespot[1158]: time="2025-02-16T19:03:10+01:00" level=debug msg="obtained new client token: AAD28P61I4F/GMiT3ZsFNsjHVl9twcIkGM6j+eRzjXbYsHdsWuLkGBB1YcBa/Ot0BGSeT/BxcnWTQJuz9AOrx+HEwbzqx2ltFRLPXsI4xps6WaSOriYHy9u7Eaag6wuzByem8urAkR2GuET9+R32WM5Swh8sIFo42NuEpuS5ZbDAz1C2BLuSeg4nCn6D3SzdjgdqLudu0ONO8xQxruSKoSGkx5Dwbby6zS5PZv/p1Z1FFhgOGVsV8+lUFhI=" Feb 16 19:03:10 volumio3 go-librespot[1158]: time="2025-02-16T19:03:10+01:00" level=debug msg="completed keyexchange" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="completed challenge" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="authenticated as p74zljw5643xc2hurw3diay1i" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="authenticated as p74zljw5643xc2hurw3diay1i" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="dealer connection opened" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=info msg="accepted zeroconf user p74zljw5643xc2hurw3diay1i from moto g84 5G" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="received connection id: YTczNzgwNWEtNTcwMy00ODUwLWEyMjUtODQ3ODA4MmFlMmY5K2RlYWxlcit0Y3A6Ly8wYWNhNWEwMi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQTJFQ0VGNUVFMjVDNTU0NEQxOTcxMTU3NTk5M0U2NzkwQjJCMTk2NjQ2Q0M2N0E2MDk3RTNERDg1REM3QzhDOQ==" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 16 19:03:11 volumio3 volumio[805]: info: Initializing connection to go-librespot Websocket Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="autoplay enabled: false" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="new websocket client" Feb 16 19:03:11 volumio3 volumio[805]: info: Connection to go-librespot Websocket established Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="handling transfer player command from e5229ef9e9228240ccd4ed5e7f029107492c159e" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:7JiB7NFZRGGoPOTMUhRZqt" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=trace msg="fetched new page 0 with 40 items (list: 40)" uri="spotify:playlist:7JiB7NFZRGGoPOTMUhRZqt" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="shuffled context with seed 2020849551027504070 (len: 40, keep: 30)" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="loading track (paused: true, position: 227496ms)" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=trace msg="emitting websocket event: will_play" Feb 16 19:03:11 volumio3 volumio[805]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6dsq7Nt5mIFzvm5kIYNORy","play_origin":"playlist"}} Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (45c2f769f064ea9d0c3a664d917c9bbdbc9a0c3f)" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:11 volumio3 go-librespot[1158]: time="2025-02-16T19:03:11+01:00" level=debug msg="requested aes key for file 45c2f769f064ea9d0c3a664d917c9bbdbc9a0c3f, gid: 6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1693" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1293" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched first chunk of 19, total size is 9622360 bytes" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched chunk 18/18, size: 185176" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=debug msg="fetched chunk 17/18, size: 524288" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:12 volumio3 go-librespot[1158]: time="2025-02-16T19:03:12+01:00" level=trace msg="seek to 227496ms (diff: 58ms, samples: 10032573, bytes: 9305643)" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:13 volumio3 kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="created new output device" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=info msg="loaded track \"15 Step\" (paused: true, position: 227496ms, duration: 237293ms, prefetched: false)" uri="spotify:track:6dsq7Nt5mIFzvm5kIYNORy" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=trace msg="emitting websocket event: metadata" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=trace msg="emitting websocket event: active" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="sending successful reply for dealer request" Feb 16 19:03:13 volumio3 volumio[805]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6dsq7Nt5mIFzvm5kIYNORy","name":"15 Step","artist_names":["Radiohead"],"album_name":"In Rainbows","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0234733f87148c2fbe0176abdb","position":227496,"duration":237293,"release_date":"year:2007 month:12 day:28","track_number":1,"disc_number":1}} Feb 16 19:03:13 volumio3 volumio[805]: SPOTIFY: received: {"type":"active","data":null} Feb 16 19:03:13 volumio3 volumio[805]: info: Aligning Spotify Volume to Volumio Volume Feb 16 19:03:13 volumio3 volumio[805]: info: CoreCommandRouter::volumioGetState Feb 16 19:03:13 volumio3 volumio[805]: info: CorePlayQueue::getTrack 0 Feb 16 19:03:13 volumio3 volumio[805]: info: Setting Spotify Volume from Volumio: 100 Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 19:03:13 volumio3 go-librespot[1158]: time="2025-02-16T19:03:13+01:00" level=trace msg="emitting websocket event: paused" Feb 16 19:03:13 volumio3 volumio[805]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6dsq7Nt5mIFzvm5kIYNORy","play_origin":"playlist"}} Feb 16 19:03:13 volumio3 volumio[805]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 19:03:13 volumio3 volumio[805]: TypeError: Cannot read property 'service' of undefined Feb 16 19:03:13 volumio3 volumio[805]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Feb 16 19:03:13 volumio3 volumio[805]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Feb 16 19:03:13 volumio3 volumio[805]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Feb 16 19:03:13 volumio3 volumio[805]: at WebSocket.emit (events.js:315:20) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.emit (events.js:315:20) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 16 19:03:13 volumio3 volumio[805]: at writeOrBuffer (internal/streams/writable.js:358:12) Feb 16 19:03:13 volumio3 volumio[805]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Feb 16 19:03:13 volumio3 volumio[805]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 16 19:03:13 volumio3 volumio[805]: at Socket.emit (events.js:315:20) Feb 16 19:03:13 volumio3 volumio[805]: at addChunk (internal/streams/readable.js:309:12) Feb 16 19:03:13 volumio3 volumio[805]: at readableAddChunk (internal/streams/readable.js:284:9) Feb 16 19:03:13 volumio3 volumio[805]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 19:03:14 volumio3 sudo[1242]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-16 19:02 Feb 16 19:03:14 volumio3 sudo[1242]: 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"