-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2025-02-26 20:00:04 CET. -- Feb 26 19:59:00 volumio3 dbus-daemon[541]: [system] Successfully activated service 'org.freedesktop.timedate1' Feb 26 19:59:00 volumio3 systemd[1]: Started Time & Date Service. Feb 26 19:59:29 volumio3 systemd-timedated[927]: Changed local time to Wed Feb 26 19:59:29 2025 Feb 26 19:59:29 volumio3 sudo[925]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:29 volumio3 volumio-time-update[553]: volumio-time-update-util: System time updated successfully. Feb 26 19:59:29 volumio3 systemd[1]: Started Volumio Time Update Utility. Feb 26 19:59:29 volumio3 systemd[1]: Reached target Multi-User System. Feb 26 19:59:29 volumio3 systemd[1]: Started Run on boot service by wd. Feb 26 19:59:29 volumio3 systemd[1]: Reached target Graphical Interface. Feb 26 19:59:29 volumio3 systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 26 19:59:29 volumio3 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 26 19:59:29 volumio3 systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 26 19:59:29 volumio3 systemd[1]: Startup finished in 14.642s (kernel) + 20.445s (userspace) = 35.088s. Feb 26 19:59:30 volumio3 volumio-remote-updater[550]: [2025-02-26 19:59:30] [info] asio async_connect error: system:111 (Connection refused) Feb 26 19:59:30 volumio3 volumio-remote-updater[550]: [2025-02-26 19:59:30] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 26 19:59:30 volumio3 volumio-remote-updater[550]: [2025-02-26 19:59:30] [error] handle_connect error: Underlying Transport Error Feb 26 19:59:31 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:31 volumio3 volumio[892]: info: ----- Volumio3 ---- Feb 26 19:59:31 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:31 volumio3 volumio[892]: info: ----- System startup ---- Feb 26 19:59:31 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:33 volumio3 volumio[892]: info: MYVOLUMIO Environment detected Feb 26 19:59:34 volumio3 volumio[892]: info: Plugin folders cleanup Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning into folder /volumio/app/plugins/ Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category audio_interface Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category miscellanea Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category music_service Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category plugins.json Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category system_controller Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category user_interface Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning into folder /data/plugins/ Feb 26 19:59:34 volumio3 volumio[892]: info: Scanning category music_service Feb 26 19:59:34 volumio3 volumio[892]: info: Plugin folders cleanup completed Feb 26 19:59:34 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:34 volumio3 volumio[892]: info: ----- Core plugins startup ---- Feb 26 19:59:34 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:34 volumio3 volumio[892]: info: Loading plugins from folder /volumio/app/plugins/ Feb 26 19:59:34 volumio3 volumio[892]: info: Adding plugin upnp to MyMusic Plugins Feb 26 19:59:34 volumio3 volumio[892]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 26 19:59:34 volumio3 volumio[892]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 26 19:59:34 volumio3 volumio[892]: info: Loading plugins from folder /data/plugins/ Feb 26 19:59:34 volumio3 volumio[892]: info: Loading plugin "system"... Feb 26 19:59:34 volumio3 volumio[892]: info: Loading plugin "appearance"... Feb 26 19:59:36 volumio3 volumio[892]: info: Loading plugin "network"... Feb 26 19:59:37 volumio3 volumio[892]: info: Refreshing Cached IP Addresses Feb 26 19:59:37 volumio3 sudo[949]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 26 19:59:37 volumio3 sudo[949]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:37 volumio3 sudo[949]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:37 volumio3 sudo[951]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 26 19:59:37 volumio3 sudo[951]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "services"... Feb 26 19:59:37 volumio3 sudo[951]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "alsa_controller"... Feb 26 19:59:37 volumio3 sudo[960]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 26 19:59:37 volumio3 sudo[960]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:37 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "wizard"... Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "networkfs"... Feb 26 19:59:37 volumio3 volumio[892]: info: Starting Udev Watcher for removable devices Feb 26 19:59:37 volumio3 sudo[977]: 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 26 19:59:37 volumio3 sudo[977]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:37 volumio3 volumio[892]: info: Ignoring mount for partition: boot Feb 26 19:59:37 volumio3 volumio[892]: info: Ignoring mount for partition: volumio Feb 26 19:59:37 volumio3 volumio[892]: info: Ignoring mount for partition: volumio_data Feb 26 19:59:37 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "volumio_command_line_client"... Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "upnp"... Feb 26 19:59:37 volumio3 volumio[892]: info: [1740596377646] Starting Upmpd Daemon Feb 26 19:59:37 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "my_music"... Feb 26 19:59:37 volumio3 volumio[892]: info: Loading plugin "mpd"... Feb 26 19:59:37 volumio3 kernel: Key type cifs.spnego registered Feb 26 19:59:37 volumio3 kernel: Key type cifs.idmap registered Feb 26 19:59:37 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 26 19:59:37 volumio3 kernel: CIFS: Attempting to mount //192.168.99.31/bu/music Feb 26 19:59:38 volumio3 kernel: cryptd: max_cpu_qlen set to 1000 Feb 26 19:59:38 volumio3 sudo[977]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:38 volumio3 volumio[892]: info: Loading plugin "upnp_browser"... Feb 26 19:59:39 volumio3 volumio[892]: info: Loading plugin "alarm-clock"... Feb 26 19:59:39 volumio3 sudo[960]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "airplay_emulation"... Feb 26 19:59:40 volumio3 volumio[892]: info: Starting Shairport Sync Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "last_100"... Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "webradio"... Feb 26 19:59:40 volumio3 volumio-remote-updater[550]: [2025-02-26 19:59:40] [connect] Successful connection Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "i2s_dacs"... Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "volumiodiscovery"... Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** For more information see Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 26 19:59:40 volumio3 volumio[892]: *** WARNING *** For more information see Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** For more information see Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 26 19:59:40 volumio3 node[892]: *** WARNING *** For more information see Feb 26 19:59:40 volumio3 volumio[892]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 26 19:59:40 volumio3 volumio[892]: info: Discovery: Started advertising with name: Volumio3 Feb 26 19:59:40 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 26 19:59:40 volumio3 volumio[892]: info: Loading plugin "spop"... Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "outputs"... Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "albumart"... Feb 26 19:59:43 volumio3 volumio[892]: info: Plugin example_plugin is not enabled Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "inputs"... Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "updater_comm"... Feb 26 19:59:43 volumio3 systemd[1]: systemd-fsckd.service: Succeeded. Feb 26 19:59:43 volumio3 volumio[892]: info: Plugin mpdemulation is not enabled Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "rest_api"... Feb 26 19:59:43 volumio3 volumio[892]: info: Loading plugin "websocket"... Feb 26 19:59:43 volumio3 volumio[892]: info: Starting Socket.io Server version 2.3.0 Feb 26 19:59:43 volumio3 volumio[892]: info: Loading i18n strings for locale en Feb 26 19:59:44 volumio3 volumio[892]: Updating browse sources language Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:44 volumio3 volumio[892]: Forking 3 albumart workers Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::initPlayerControls Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 19:59:44 volumio3 volumio[892]: Express server listening on port 3000 Feb 26 19:59:44 volumio3 volumio[892]: [Metrics] WebUI: 14s 248.77ms Feb 26 19:59:44 volumio3 volumio[892]: info: CoreStateMachine::resetVolumioState Feb 26 19:59:44 volumio3 volumio[892]: info: CoreStateMachine::getcurrentVolume Feb 26 19:59:44 volumio3 volumio[892]: info: CoreCommandRouter::volumioRetrievevolume Feb 26 19:59:44 volumio3 volumio[892]: info: Volumio Network Manager: Network status updated: 1 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.21 UA: Mozilla/5.0 (X11; Linux x86_64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 1 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.16 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 2 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.21 UA: Mozilla/5.0 (X11; Linux x86_64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 3 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.16 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 4 Feb 26 19:59:45 volumio3 volumio-remote-updater[550]: [2025-02-26 19:59:45] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1740596380 101 Feb 26 19:59:45 volumio3 volumio[892]: 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: 5 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.21 UA: Mozilla/5.0 (X11; Linux x86_64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 6 Feb 26 19:59:45 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.16 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 7 Feb 26 19:59:45 volumio3 volumio[892]: info: Reloading queue from file Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:45 volumio3 volumio[892]: info: Setting Device type: Raspberry PI Feb 26 19:59:45 volumio3 volumio[892]: info: Completed loading Core Plugins Feb 26 19:59:45 volumio3 volumio[892]: info: Preparing to generate the ALSA configuration file Feb 26 19:59:45 volumio3 volumio[892]: info: VolumeController:: Volume=0 Mute =false Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::pushState Feb 26 19:59:45 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::volumioPushState Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::updateTrackBlock Feb 26 19:59:45 volumio3 volumio[892]: info: CorePlayQueue::getTrackBlock Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::volumioRetrievevolume Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::setRepeat false single undefined Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::pushState Feb 26 19:59:45 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::volumioPushState Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::setRandom false Feb 26 19:59:45 volumio3 volumio[892]: info: CoreStateMachine::pushState Feb 26 19:59:45 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::volumioPushState Feb 26 19:59:45 volumio3 volumio[892]: info: Asound.conf file unchanged, so no further update is needed Feb 26 19:59:45 volumio3 volumio[892]: info: Output device has changed, restarting MPD Feb 26 19:59:45 volumio3 volumio[892]: info: Output device has changed, restarting Shairport Sync Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:45 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:45 volumio3 sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 26 19:59:45 volumio3 sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:45 volumio3 sudo[1058]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:45 volumio3 sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 26 19:59:45 volumio3 sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:45 volumio3 volumio[892]: Starting albumart workers Feb 26 19:59:45 volumio3 volumio[892]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 19:59:45 volumio3 volumio[892]: Starting albumart workers Feb 26 19:59:45 volumio3 volumio[892]: info: ___________ START PLUGINS ___________ Feb 26 19:59:45 volumio3 volumio[892]: info: ControllerMpd::onStart: Initializing MPD Feb 26 19:59:45 volumio3 volumio[892]: info: Creating MPD Configuration file Feb 26 19:59:45 volumio3 systemd[1]: Stopping Music Player Daemon... Feb 26 19:59:45 volumio3 volumio[892]: Starting albumart workers Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 19:59:46 volumio3 volumio[892]: info: [1740596386024] CoreMusicLibrary::Adding element Media Servers Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:46 volumio3 sudo[1067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 26 19:59:46 volumio3 sudo[1067]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:46 volumio3 sudo[1069]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 26 19:59:46 volumio3 sudo[1067]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:46 volumio3 sudo[1069]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:46 volumio3 systemd[1]: mpd.service: Succeeded. Feb 26 19:59:46 volumio3 systemd[1]: Stopped Music Player Daemon. Feb 26 19:59:46 volumio3 volumio[892]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:46 volumio3 systemd[1]: Starting Music Player Daemon... Feb 26 19:59:46 volumio3 volumio[892]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 19:59:46 volumio3 volumio[892]: info: [1740596386466] CoreMusicLibrary::Adding element Last_100 Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 19:59:46 volumio3 volumio[892]: info: [1740596386472] CoreMusicLibrary::Adding element Webradio Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 19:59:46 volumio3 volumio[892]: info: Initializing BBC Radios Feb 26 19:59:46 volumio3 sudo[1075]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 26 19:59:46 volumio3 sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:46 volumio3 sudo[1075]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:46 volumio3 volumio[892]: info: Creating Spotify config file Feb 26 19:59:46 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:47 volumio3 volumio[892]: info: Volumio Calling Home Feb 26 19:59:47 volumio3 volumio[892]: info: Discovery: adding d42e7524-9646-4121-adf5-eb9b6d28e6a7 Feb 26 19:59:47 volumio3 volumio[892]: info: Discovery: Found device Volumio3 Feb 26 19:59:47 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetState Feb 26 19:59:47 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:47 volumio3 volumio[892]: info: MPD Permissions set Feb 26 19:59:47 volumio3 volumio[892]: info: MPD Permissions set Feb 26 19:59:47 volumio3 volumio[892]: info: VolumeController:: Volume=0 Mute =false Feb 26 19:59:47 volumio3 volumio[892]: info: CoreStateMachine::pushState Feb 26 19:59:47 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:47 volumio3 volumio[892]: info: CoreCommandRouter::volumioPushState Feb 26 19:59:47 volumio3 sudo[1127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 26 19:59:47 volumio3 sudo[1127]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:47 volumio3 sudo[1127]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:47 volumio3 sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 26 19:59:47 volumio3 sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:47 volumio3 sudo[1130]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:47 volumio3 volumio[892]: info: Volumio called home Feb 26 19:59:48 volumio3 volumio[892]: info: Spotify config file written Feb 26 19:59:48 volumio3 volumio[892]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 sudo[1137]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 26 19:59:48 volumio3 sudo[1137]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 19:59:48 volumio3 go-librespot[1147]: Librespot-go daemon starting... Feb 26 19:59:48 volumio3 systemd[1]: Started go-librespot Daemon. Feb 26 19:59:48 volumio3 sudo[1137]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:48 volumio3 systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 26 19:59:48 volumio3 systemd[1]: mpd.service: Failed with result 'protocol'. Feb 26 19:59:48 volumio3 systemd[1]: Failed to start Music Player Daemon. Feb 26 19:59:48 volumio3 sudo[1060]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:48 volumio3 sudo[1069]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:48 volumio3 systemd[1]: Starting Music Player Daemon... Feb 26 19:59:48 volumio3 volumio[892]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 26 19:59:48 volumio3 volumio[892]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 26 19:59:48 volumio3 volumio[892]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 26 19:59:48 volumio3 volumio[892]: info: Completed starting Core Plugins Feb 26 19:59:48 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:48 volumio3 volumio[892]: info: ----- MyVolumio plugins startup ---- Feb 26 19:59:48 volumio3 volumio[892]: info: ------------------------------------------- Feb 26 19:59:48 volumio3 volumio[892]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 26 19:59:48 volumio3 volumio[892]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 26 19:59:48 volumio3 volumio[892]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 26 19:59:48 volumio3 volumio[892]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 26 19:59:48 volumio3 volumio[892]: info: Starting Shairport Sync Feb 26 19:59:48 volumio3 volumio[892]: info: Starting Shairport Sync Feb 26 19:59:48 volumio3 volumio[892]: info: Starting Shairport Sync Feb 26 19:59:48 volumio3 sudo[1162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 19:59:48 volumio3 sudo[1162]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:48 volumio3 sudo[1164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 19:59:48 volumio3 sudo[1164]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:48 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.21 UA: Mozilla/5.0 (X11; Linux x86_64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 9 Feb 26 19:59:48 volumio3 sudo[1167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 19:59:48 volumio3 sudo[1167]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:48 volumio3 go-librespot[1147]: time="2025-02-26T19:59:48+01:00" level=info msg="generated new device id: 949761b7403db0a496313fb697e511c0dfc6ed70" Feb 26 19:59:48 volumio3 go-librespot[1147]: time="2025-02-26T19:59:48+01:00" level=debug msg="stored credentials found for xa60m3puti317444kkwsgrlme" Feb 26 19:59:48 volumio3 sudo[1160]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 26 19:59:48 volumio3 sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:48 volumio3 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 26 19:59:48 volumio3 systemd[1]: shairport-sync.service: Succeeded. Feb 26 19:59:48 volumio3 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 26 19:59:48 volumio3 sudo[1160]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:48 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetState Feb 26 19:59:48 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetState Feb 26 19:59:49 volumio3 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 26 19:59:49 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:49 volumio3 sudo[1167]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:49 volumio3 sudo[1162]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:49 volumio3 sudo[1164]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:49 volumio3 sudo[1173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 26 19:59:49 volumio3 sudo[1173]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 19:59:49 volumio3 volumio[892]: verbose: New Socket.io Connection to 192.168.99.24 from 192.168.99.16 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 10 Feb 26 19:59:49 volumio3 systemd[1]: Started UPnP Renderer front-end to MPD. Feb 26 19:59:49 volumio3 sudo[1173]: pam_unix(sudo:session): session closed for user root Feb 26 19:59:49 volumio3 volumio[892]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 26 19:59:49 volumio3 volumio[892]: SPOTIFY: BQBY_frTho6WtFikj9Sy4AhilLXg95QX7dqO9eEuy-y_7Ic3_A-78YHqkroBoxyYo0IM-iScPTsaGbFB6Mgx19gmatYDuR-A8erx5BL9WyrvSlomeXDB-VViymGSfkV4gQ4LzIoSNqrrDUmm6ugNfmCGWAZOcp5f5EyO6TlxNPh96VGR70X6AWqinqlZlMMWPV155lkdxUqM2hjMQv12v8N6bpqI6lhOEaB8zsIfzHefsGDb_mHTmukxnb5qbxguqn-bE42NRe676GcuX3Uz9oZIIITD-JwYHWyvVkk Feb 26 19:59:49 volumio3 volumio[892]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 26 19:59:49 volumio3 volumio[892]: info: New Spotify access token = BQBY_frTho6WtFikj9Sy4AhilLXg95QX7dqO9eEuy-y_7Ic3_A-78YHqkroBoxyYo0IM-iScPTsaGbFB6Mgx19gmatYDuR-A8erx5BL9WyrvSlomeXDB-VViymGSfkV4gQ4LzIoSNqrrDUmm6ugNfmCGWAZOcp5f5EyO6TlxNPh96VGR70X6AWqinqlZlMMWPV155lkdxUqM2hjMQv12v8N6bpqI6lhOEaB8zsIfzHefsGDb_mHTmukxnb5qbxguqn-bE42NRe676GcuX3Uz9oZIIITD-JwYHWyvVkk Feb 26 19:59:49 volumio3 volumio[892]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 26 19:59:49 volumio3 volumio[892]: info: Listing playlists Feb 26 19:59:49 volumio3 volumio[892]: info: Upmpdcli Daemon Started Feb 26 19:59:49 volumio3 volumio[892]: info: Shairport-Sync Started Feb 26 19:59:49 volumio3 volumio[892]: Error adding Membership: Error: addMembership EINVAL Feb 26 19:59:49 volumio3 volumio[892]: info: Shairport-Sync Started Feb 26 19:59:49 volumio3 volumio[892]: info: Shairport-Sync Started Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetState Feb 26 19:59:49 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetQueue Feb 26 19:59:49 volumio3 volumio[892]: info: CoreStateMachine::getQueue Feb 26 19:59:49 volumio3 volumio[892]: info: CorePlayQueue::getQueue Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetVisibleSources Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:49 volumio3 volumio[892]: info: Listing playlists Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+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 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+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 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+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 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+01:00" level=debug msg="zeroconf server listening on port 36769" Feb 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+01:00" level=debug msg="obtained new client token: AACugyzhfjLGKNa5MtAGDx5fdfqrqrSvFi5YRXyYBArOLCqafJ00xAQ4RCKlJyiCyv5LNR87rbK/x63v2/jXF9TDkZe8qHaHocX8mdt+0e0bGYQuo18fI+J7UTgMrUB7P85O73ObpDhxjnNhUx/iTvKsYbi62teuef3JIYkyG1gyuDOpJTYMK7msVy9AVywpXs1+UA0t8QoUVLdLxLnsuHJKQv7l9LqRX5EVvI5lC3XOU8Fu70Aaf0GYnXI=" Feb 26 19:59:49 volumio3 volumio[892]: 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 26 19:59:49 volumio3 volumio[892]: info: Spotify Successfully logged in Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 19:59:49 volumio3 volumio[892]: info: [1740596389885] CoreMusicLibrary::Adding element Spotify Feb 26 19:59:49 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 19:59:49 volumio3 volumio[892]: Cannot find translation for source Spotify Feb 26 19:59:49 volumio3 go-librespot[1147]: time="2025-02-26T19:59:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Feb 26 19:59:49 volumio3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 19:59:49 volumio3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 19:59:50 volumio3 systemd[1]: systemd-hostnamed.service: Succeeded. Feb 26 19:59:51 volumio3 volumio[892]: info: go-librespot daemon successfully initialized Feb 26 19:59:51 volumio3 mpd[1171]: Feb 26 19:59 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 26 19:59:52 volumio3 systemd[1]: Started Music Player Daemon. Feb 26 19:59:52 volumio3 volumio[892]: Upnp client error: Error: This socket has been ended by the other party Feb 26 19:59:52 volumio3 mpd_monitor.sh[552]: MPD restarted due to no mpc output. Feb 26 19:59:52 volumio3 volumio[892]: error: MPD error: The expression evaluated to a falsy value: Feb 26 19:59:52 volumio3 volumio[892]: assert.ok(self.idling) Feb 26 19:59:52 volumio3 volumio[892]: error: The expression evaluated to a falsy value: Feb 26 19:59:52 volumio3 volumio[892]: assert.ok(self.idling) Feb 26 19:59:52 volumio3 volumio[892]: error: updateQueue error: null Feb 26 19:59:53 volumio3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 26 19:59:53 volumio3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 26 19:59:53 volumio3 systemd[1]: Stopped go-librespot Daemon. Feb 26 19:59:53 volumio3 systemd[1]: Started go-librespot Daemon. Feb 26 19:59:53 volumio3 go-librespot[1188]: Librespot-go daemon starting... Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=info msg="generated new device id: 4961b545260107fe87661243e9b68378e356fd0a" Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="stored credentials found for xa60m3puti317444kkwsgrlme" Feb 26 19:59:53 volumio3 volumio[1177]: Generating RSA private key, 4096 bit long modulus (2 primes) Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="zeroconf server listening on port 37863" Feb 26 19:59:53 volumio3 go-librespot[1188]: time="2025-02-26T19:59:53+01:00" level=debug msg="obtained new client token: AACylJKei4mw/EOOsAmMbJij5+i6eZBnn4ELYpwBR2YOmrH6BoNryqjvS+JO6jEqjJG65FbJimTOJrbMMaV0d5KfiagRcYRtARhwPbJ859V03XMNbncP4KI0ymPoUBT7Ym7zmSpnWSL6wkgn7oxOrfQoPJHzChLcJ0ZhMu9r+Ljusho+H6gtJ1iGHrDeiIenHNLlpT+8xxIjNjfQCCz0abj3Bi8Bll68F6ydaEopNTcXuonJy1/PVmLR3io=" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="completed keyexchange" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="completed challenge" Feb 26 19:59:54 volumio3 volumio[892]: info: Initializing connection to go-librespot Websocket Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="new websocket client" Feb 26 19:59:54 volumio3 volumio[892]: info: Connection to go-librespot Websocket established Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="authenticated as xa60m3puti317444kkwsgrlme" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="dealer connection opened" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="initializing zeroconf session, username: xa60m3puti317444kkwsgrlme" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="autoplay enabled: false" Feb 26 19:59:54 volumio3 go-librespot[1188]: time="2025-02-26T19:59:54+01:00" level=debug msg="received connection id: M2QxOTRmNzAtYTcyYS00MzU3LTlkNjAtMjJlNzVkYjNmNjc0K2RlYWxlcit0Y3A6Ly8wYWNhNWEzNi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDdBMkI1REFFMkFFQ0QyRUIyMDZGNUM0MDNGRjAwNUI5N0M3NzA2NDM3Q0ZCOTM3RTFCMkY2MENBMUQ0RTU2Qw==" Feb 26 19:59:55 volumio3 go-librespot[1188]: time="2025-02-26T19:59:55+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 26 19:59:57 volumio3 volumio[892]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin bluetooth to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin multiroom to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin metavolumio to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin cd_controller to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 26 19:59:57 volumio3 volumio[892]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 26 19:59:59 volumio3 systemd[1]: systemd-timedated.service: Succeeded. Feb 26 19:59:59 volumio3 kernel: CIFS: enabling forceuid mount option implicitly because uid= option is specified Feb 26 19:59:59 volumio3 kernel: CIFS: enabling forcegid mount option implicitly because gid= option is specified Feb 26 19:59:59 volumio3 kernel: CIFS: Attempting to mount //192.168.99.20/share_smb Feb 26 19:59:59 volumio3 volumio[892]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 26 19:59:59 volumio3 volumio[892]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 26 19:59:59 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:59 volumio3 volumio[892]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 19:59:59 volumio3 volumio[892]: info: Starting MyVolumio Remote Streaming Endpoints Feb 26 19:59:59 volumio3 volumio[892]: info: MyVolumio login type: Token Feb 26 19:59:59 volumio3 volumio[892]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 26 19:59:59 volumio3 volumio[892]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="handling transfer player command from ef243ed07364d61e82f34687a10c0cc839f4f144" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWTSKFpOdYF1r" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=trace msg="fetched new page 0 with 52 items (list: 52)" uri="spotify:playlist:37i9dQZF1DWTSKFpOdYF1r" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="loading track (paused: false, position: 122482ms)" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=trace msg="emitting websocket event: will_play" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1138" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="selected format OGG_VORBIS_320 (09ba712cd7e98ed3ee893536bd9f5a9a3ca3a92f)" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:01 volumio3 go-librespot[1188]: time="2025-02-26T20:00:01+01:00" level=debug msg="requested aes key for file 09ba712cd7e98ed3ee893536bd9f5a9a3ca3a92f, gid: 60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched first chunk of 18, total size is 9164276 bytes" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 11/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 13/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 10/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 volumio[892]: info: Starting Streaming Service Transparent Proxy Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 12/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=trace msg="seek to 122482ms (diff: 131ms, samples: 5401456, bytes: 5335181)" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 volumio[892]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 26 20:00:02 volumio3 volumio[892]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 26 20:00:02 volumio3 volumio[892]: info: Streaming services startup Feb 26 20:00:02 volumio3 volumio[892]: info: Starting Streaming Daemon Feb 26 20:00:02 volumio3 kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+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 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=debug msg="created new output device" Feb 26 20:00:02 volumio3 go-librespot[1188]: time="2025-02-26T20:00:02+01:00" level=info msg="loaded track \"Electricity - Remastered 2003\" (paused: false, position: 122482ms, duration: 219066ms, prefetched: false)" uri="spotify:track:60TmG8cFPMBo7kTTFOLiAB" Feb 26 20:00:02 volumio3 sudo[1251]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 26 20:00:02 volumio3 sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 20:00:03 volumio3 volumio[892]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 26 20:00:03 volumio3 sudo[1251]: pam_unix(sudo:session): session closed for user root Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=trace msg="scheduling prefetch in 67s" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=trace msg="emitting websocket event: metadata" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=trace msg="emitting websocket event: active" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=debug msg="sending successful reply for dealer request" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 20:00:03 volumio3 go-librespot[1188]: time="2025-02-26T20:00:03+01:00" level=trace msg="emitting websocket event: playing" Feb 26 20:00:03 volumio3 volumio[892]: info: Getting Spotify volume Feb 26 20:00:03 volumio3 volumio[892]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:60TmG8cFPMBo7kTTFOLiAB","play_origin":"playlist/ondemand"}} Feb 26 20:00:03 volumio3 volumio[892]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:60TmG8cFPMBo7kTTFOLiAB","name":"Electricity - Remastered 2003","artist_names":["Orchestral Manoeuvres In The Dark"],"album_name":"Orchestral Manoeuvres In The Dark (Remastered 2003)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020055911860baf382f46aeffa","position":122482,"duration":219066,"release_date":"year:1980 month:2 day:22","track_number":4,"disc_number":1}} Feb 26 20:00:03 volumio3 volumio[892]: SPOTIFY: received: {"type":"active","data":null} Feb 26 20:00:03 volumio3 volumio[892]: info: Aligning Spotify Volume to Volumio Volume Feb 26 20:00:03 volumio3 volumio[892]: info: CoreCommandRouter::volumioGetState Feb 26 20:00:03 volumio3 volumio[892]: info: CorePlayQueue::getTrack 0 Feb 26 20:00:03 volumio3 volumio[892]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:60TmG8cFPMBo7kTTFOLiAB","play_origin":"playlist/ondemand"}} Feb 26 20:00:03 volumio3 volumio[892]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 20:00:03 volumio3 volumio[892]: TypeError: Cannot read property 'service' of undefined Feb 26 20:00:03 volumio3 volumio[892]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Feb 26 20:00:03 volumio3 volumio[892]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Feb 26 20:00:03 volumio3 volumio[892]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Feb 26 20:00:03 volumio3 volumio[892]: at WebSocket.emit (events.js:315:20) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.emit (events.js:315:20) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 26 20:00:03 volumio3 volumio[892]: at writeOrBuffer (internal/streams/writable.js:358:12) Feb 26 20:00:03 volumio3 volumio[892]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Feb 26 20:00:03 volumio3 volumio[892]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 26 20:00:03 volumio3 volumio[892]: at Socket.emit (events.js:315:20) Feb 26 20:00:03 volumio3 volumio[892]: at addChunk (internal/streams/readable.js:309:12) Feb 26 20:00:03 volumio3 volumio[892]: at readableAddChunk (internal/streams/readable.js:284:9) Feb 26 20:00:03 volumio3 volumio[892]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 20:00:04 volumio3 sudo[1267]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-26 19:59 Feb 26 20:00:04 volumio3 sudo[1267]: 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"