-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2025-06-11 19:48:21 CEST. -- Jun 11 19:47:05 volumio volumio[1050]: info: CorePlayQueue::getTrack 0 Jun 11 19:47:05 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:05 volumio volumio[1050]: info: Prefetching next song Jun 11 19:47:05 volumio volumio[1050]: info: [1749664025345] ControllerQobuz::prefetch Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/326219" Jun 11 19:47:05 volumio volumio[1050]: STREAMING PROXY: Handling url /?data=qobuz://song/326219 Jun 11 19:47:05 volumio volumio[1050]: info: Executing endpoint getStreamUrlqobuz Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 11 19:47:05 volumio volumio[1050]: info: getStreamUrl took 399 milliseconds Jun 11 19:47:05 volumio volumio[1050]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=1889012&eid=326219&fmt=6&profile=raw&app_id=539451548&cid=1848830&etsp=1749667625&hmac=gm-GMys98PyL3QZxTDe4Xazvm2U Jun 11 19:47:05 volumio volumio[1050]: STREAMING PROXY: Response: 200, length: 24611224 Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/326219" Jun 11 19:47:05 volumio volumio[1050]: STREAMING PROXY: Client dropped request, destroying Jun 11 19:47:05 volumio volumio[1050]: info: Jun 11 19:47:05 volumio volumio[1050]: ---------------------------- MPD announces system playlist update Jun 11 19:47:05 volumio volumio[1050]: info: Ignoring MPD Status Update Jun 11 19:47:05 volumio volumio[1050]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/326219" took 3 milliseconds Jun 11 19:47:05 volumio volumio[1050]: STREAMING PROXY: Handling url /?data=qobuz://song/326219 Jun 11 19:47:05 volumio volumio[1050]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand consume 1 Jun 11 19:47:05 volumio volumio[1050]: info: Jun 11 19:47:05 volumio volumio[1050]: ---------------------------- MPD announces state update: options Jun 11 19:47:05 volumio volumio[1050]: info: ------------------------------ 5ms Jun 11 19:47:05 volumio volumio[1050]: info: sendMpdCommand consume 1 took 2 milliseconds Jun 11 19:47:05 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:47:05 volumio volumio[1050]: info: sendMpdCommand status took 3 milliseconds Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 11 19:47:05 volumio volumio[1050]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 11 19:47:05 volumio volumio[1050]: verbose: ControllerMpd::parseTrackInfo Jun 11 19:47:05 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:47:05 volumio volumio[1050]: info: CorePlayQueue::getTrack 0 Jun 11 19:47:05 volumio volumio[1050]: verbose: STATE SERVICE {"status":"play","position":0,"seek":256368,"duration":261,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"473 Kbps","isStreaming":false,"title":"326218","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/326218","trackType":"qobuz"} Jun 11 19:47:05 volumio volumio[1050]: verbose: CURRENT POSITION 0 Jun 11 19:47:05 volumio volumio[1050]: info: CoreStateMachine::syncState stateService play Jun 11 19:47:05 volumio volumio[1050]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:47:05 volumio volumio[1050]: info: Received an update from plugin. extracting info from payload Jun 11 19:47:05 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:05 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:05 volumio volumio[1050]: info: ------------------------------ 46ms Jun 11 19:47:05 volumio volumio[1050]: info: Executing endpoint getStreamUrlqobuz Jun 11 19:47:05 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 11 19:47:06 volumio volumio[1050]: info: getStreamUrl took 412 milliseconds Jun 11 19:47:06 volumio volumio[1050]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=1889012&eid=326219&fmt=6&profile=raw&app_id=539451548&cid=1848830&etsp=1749667626&hmac=KhY0BLKE6f6w7fLGOCI_wkuYVOQ Jun 11 19:47:06 volumio volumio[1050]: STREAMING PROXY: Response: 200, length: 24611224 Jun 11 19:47:08 volumio volumio[1050]: STREAMING PROXY: Client dropped request, destroying Jun 11 19:47:09 volumio volumio[1050]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:47:09 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:09 volumio go-librespot[1214]: time="2025-06-11T19:47:09+02:00" level=trace msg="sent dealer ping" Jun 11 19:47:09 volumio go-librespot[1214]: time="2025-06-11T19:47:09+02:00" level=trace msg="received dealer pong" Jun 11 19:47:10 volumio volumio[1050]: info: Jun 11 19:47:10 volumio volumio[1050]: ---------------------------- MPD announces system playlist update Jun 11 19:47:10 volumio volumio[1050]: info: Ignoring MPD Status Update Jun 11 19:47:10 volumio volumio[1050]: info: Jun 11 19:47:10 volumio volumio[1050]: ---------------------------- MPD announces state update: player Jun 11 19:47:10 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:47:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:47:10 volumio volumio[1050]: info: ------------------------------ 3ms Jun 11 19:47:10 volumio volumio[1050]: info: sendMpdCommand status took 2 milliseconds Jun 11 19:47:10 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:47:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 11 19:47:10 volumio volumio[1050]: info: sendMpdCommand playlistinfo took 0 milliseconds Jun 11 19:47:10 volumio volumio[1050]: verbose: ControllerMpd::parseTrackInfo Jun 11 19:47:10 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"640 Kbps","isStreaming":false,"title":"326219","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/326219","trackType":"qobuz"} Jun 11 19:47:10 volumio volumio[1050]: verbose: CURRENT POSITION 1 Jun 11 19:47:10 volumio volumio[1050]: info: CoreStateMachine::syncState stateService play Jun 11 19:47:10 volumio volumio[1050]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:47:10 volumio volumio[1050]: info: Received an update from plugin. extracting info from payload Jun 11 19:47:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: info: ------------------------------ 42ms Jun 11 19:47:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:47:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:22 volumio volumio[1050]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Jun 11 19:47:22 volumio sudo[4422]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 11 19:47:22 volumio sudo[4422]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:22 volumio sudo[4422]: pam_unix(sudo:session): session closed for user root Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio sudo[4425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 11 19:47:22 volumio sudo[4425]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:22 volumio volumio[1050]: info: MPD Permissions set Jun 11 19:47:22 volumio systemd[1]: Stopping Music Player Daemon... Jun 11 19:47:22 volumio systemd[1]: mpd.service: Succeeded. Jun 11 19:47:22 volumio systemd[1]: Stopped Music Player Daemon. Jun 11 19:47:22 volumio systemd[1]: Starting Music Player Daemon... Jun 11 19:47:22 volumio sudo[4431]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 11 19:47:22 volumio sudo[4431]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:22 volumio sudo[4431]: pam_unix(sudo:session): session closed for user root Jun 11 19:47:23 volumio mpd[4433]: Jun 11 19:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 11 19:47:23 volumio systemd[1]: Started Music Player Daemon. Jun 11 19:47:23 volumio sudo[4425]: pam_unix(sudo:session): session closed for user root Jun 11 19:47:23 volumio volumio[1050]: error: updateQueue error: null Jun 11 19:47:28 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 19:47:28 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 19:47:28 volumio volumio[1050]: info: Discovery: Getting this device information Jun 11 19:47:28 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:28 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:28 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 19:47:39 volumio go-librespot[1214]: time="2025-06-11T19:47:39+02:00" level=trace msg="received accesspoint ping" Jun 11 19:47:39 volumio go-librespot[1214]: time="2025-06-11T19:47:39+02:00" level=trace msg="received accesspoint pong ack" Jun 11 19:47:39 volumio go-librespot[1214]: time="2025-06-11T19:47:39+02:00" level=trace msg="sent dealer ping" Jun 11 19:47:39 volumio go-librespot[1214]: time="2025-06-11T19:47:39+02:00" level=trace msg="received dealer pong" Jun 11 19:47:45 volumio wpa_supplicant[876]: wlan0: CTRL-EVENT-DISCONNECTED bssid=30:68:93:d8:e3:81 reason=3 Jun 11 19:47:45 volumio dhcpcd[980]: wlan0: carrier lost Jun 11 19:47:45 volumio wpa_supplicant[876]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jun 11 19:47:45 volumio avahi-daemon[591]: Withdrawing address record for 192.168.1.107 on wlan0. Jun 11 19:47:45 volumio avahi-daemon[591]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.107. Jun 11 19:47:45 volumio dhcpcd[980]: wlan0: deleting route to 192.168.1.0/24 Jun 11 19:47:45 volumio avahi-daemon[591]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 11 19:47:45 volumio dhcpcd[980]: wlan0: deleting default route via 192.168.1.1 Jun 11 19:47:45 volumio volumio[1050]: info: Discovery: A device disappeared from network Jun 11 19:47:45 volumio volumio[1050]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Jun 11 19:47:46 volumio wpa_supplicant[876]: wlan0: Trying to associate with SSID 'TP-Link_E381' Jun 11 19:47:46 volumio dhcpcd[980]: wlan0: carrier acquired Jun 11 19:47:46 volumio wpa_supplicant[876]: wlan0: Associated with 30:68:93:d8:e3:81 Jun 11 19:47:46 volumio wpa_supplicant[876]: wlan0: CTRL-EVENT-CONNECTED - Connection to 30:68:93:d8:e3:81 completed [id=0 id_str=] Jun 11 19:47:46 volumio wpa_supplicant[876]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 11 19:47:46 volumio dhcpcd[980]: wlan0: IAID eb:a8:ac:9c Jun 11 19:47:46 volumio dhcpcd[980]: wlan0: carrier lost Jun 11 19:47:46 volumio dhcpcd[980]: wlan0: carrier acquired Jun 11 19:47:46 volumio dhcpcd[980]: wlan0: IAID eb:a8:ac:9c Jun 11 19:47:47 volumio dhcpcd[980]: wlan0: rebinding lease of 192.168.1.107 Jun 11 19:47:47 volumio dhcpcd[980]: wlan0: probing address 192.168.1.107/24 Jun 11 19:47:47 volumio dhcpcd[980]: wlan0: soliciting an IPv6 router Jun 11 19:47:47 volumio ntpd[813]: Deleting interface #6 wlan0, 192.168.1.107#123, interface stats: received=0, sent=0, dropped=0, active_time=238 secs Jun 11 19:47:50 volumio volumio[1050]: info: Volumio Network Manager: Network status updated: 1 Jun 11 19:47:51 volumio dhcpcd[980]: wlan0: leased 192.168.1.107 for 43320 seconds Jun 11 19:47:51 volumio avahi-daemon[591]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.107. Jun 11 19:47:51 volumio avahi-daemon[591]: New relevant interface wlan0.IPv4 for mDNS. Jun 11 19:47:51 volumio dhcpcd[980]: wlan0: adding route to 192.168.1.0/24 Jun 11 19:47:51 volumio avahi-daemon[591]: Registering new address record for 192.168.1.107 on wlan0.IPv4. Jun 11 19:47:51 volumio dhcpcd[980]: wlan0: adding default route via 192.168.1.1 Jun 11 19:47:52 volumio volumio[1050]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jun 11 19:47:53 volumio ntpd[813]: Listen normally on 7 wlan0 192.168.1.107:123 Jun 11 19:47:53 volumio ntpd[813]: new interface(s) found: waking up resolver Jun 11 19:47:57 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 19:47:57 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 19:47:57 volumio volumio[1050]: info: Discovery: Getting this device information Jun 11 19:47:57 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:47:57 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:47:57 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 19:47:59 volumio volumio[1050]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Jun 11 19:47:59 volumio sudo[4604]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 11 19:47:59 volumio sudo[4604]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio sudo[4604]: pam_unix(sudo:session): session closed for user root Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio sudo[4607]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 11 19:47:59 volumio sudo[4607]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 19:47:59 volumio volumio[1050]: info: MPD Permissions set Jun 11 19:47:59 volumio systemd[1]: Stopping Music Player Daemon... Jun 11 19:47:59 volumio systemd[1]: mpd.service: Succeeded. Jun 11 19:47:59 volumio systemd[1]: Stopped Music Player Daemon. Jun 11 19:47:59 volumio systemd[1]: Starting Music Player Daemon... Jun 11 19:47:59 volumio sudo[4613]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 11 19:47:59 volumio sudo[4613]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:47:59 volumio sudo[4613]: pam_unix(sudo:session): session closed for user root Jun 11 19:48:00 volumio volumio[1050]: info: Volumio Network Manager: Network status updated: 3 Jun 11 19:48:00 volumio mpd[4615]: Jun 11 19:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 11 19:48:00 volumio systemd[1]: Started Music Player Daemon. Jun 11 19:48:00 volumio sudo[4607]: pam_unix(sudo:session): session closed for user root Jun 11 19:48:00 volumio volumio[1050]: error: updateQueue error: null Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 19:48:08 volumio volumio[1050]: info: Retrieving Cloud Streaming UI Jun 11 19:48:08 volumio volumio[1050]: info: Getting Tidal Cloud Configuration Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 19:48:08 volumio volumio[1050]: info: Getting Qobuz Cloud Configuration Jun 11 19:48:08 volumio volumio[1050]: info: Asking plugin for UI Config Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 19:48:08 volumio volumio[1050]: info: Getting Spotify Cloud Configuration Jun 11 19:48:08 volumio volumio[1050]: info: Asking plugin for UI Config Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 19:48:08 volumio volumio[1050]: info: Saving Spotify Acccount Jun 11 19:48:08 volumio volumio[1050]: info: Got it Jun 11 19:48:08 volumio volumio[1050]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jun 11 19:48:08 volumio volumio[1050]: info: Got Tidal Cloud Configuration Jun 11 19:48:08 volumio volumio[1050]: info: Got it Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::volumioGetBrowseSources Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::volumioGetBrowseSources Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::volumioGetBrowseSources Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 11 19:48:08 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jun 11 19:48:09 volumio go-librespot[1214]: time="2025-06-11T19:48:09+02:00" level=trace msg="sent dealer ping" Jun 11 19:48:09 volumio go-librespot[1214]: time="2025-06-11T19:48:09+02:00" level=trace msg="received dealer pong" Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand update Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:10 volumio volumio[1050]: info: Jun 11 19:48:10 volumio volumio[1050]: ---------------------------- MPD announces state update: update Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand update took 4 milliseconds Jun 11 19:48:10 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:10 volumio volumio[1050]: info: Jun 11 19:48:10 volumio volumio[1050]: ---------------------------- MPD announces state update: update Jun 11 19:48:10 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand status took 14 milliseconds Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:10 volumio volumio[1050]: info: Command Router : Notfying DB Updatefalse Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::Close All Modals sent Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand status took 82 milliseconds Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand status took 82 milliseconds Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand status took 80 milliseconds Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:10 volumio volumio[1050]: info: Command Router : Notfying DB Updatefalse Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::Close All Modals sent Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:10 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 1 Jun 11 19:48:10 volumio volumio[1050]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 11 19:48:10 volumio volumio[1050]: verbose: CURRENT POSITION 1 Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::syncState stateService stop Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::play index undefined Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: [1749664090248] ControllerQobuz::clearAddPlayTrack Jun 11 19:48:10 volumio volumio[1050]: info: ------------------------------ 176ms Jun 11 19:48:10 volumio volumio[1050]: info: ------------------------------ 188ms Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand stop Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:10 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand stop took 40 milliseconds Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand clear Jun 11 19:48:10 volumio volumio[1050]: info: Jun 11 19:48:10 volumio volumio[1050]: ---------------------------- MPD announces system playlist update Jun 11 19:48:10 volumio volumio[1050]: info: Ignoring MPD Status Update Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand clear took 6 milliseconds Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/326220" Jun 11 19:48:10 volumio volumio[1050]: STREAMING PROXY: Handling url /?data=qobuz://song/326220 Jun 11 19:48:10 volumio volumio[1050]: error: updateQueue error: null Jun 11 19:48:10 volumio volumio[1050]: info: ------------------------------ 7ms Jun 11 19:48:10 volumio volumio[1050]: info: Executing endpoint getStreamUrlqobuz Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 11 19:48:10 volumio volumio[1050]: info: getStreamUrl took 475 milliseconds Jun 11 19:48:10 volumio volumio[1050]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=1889012&eid=326220&fmt=6&profile=raw&app_id=539451548&cid=1848830&etsp=1749667690&hmac=h9jWSPMK7LVzP1U48hhFY4jckDE Jun 11 19:48:10 volumio volumio[1050]: STREAMING PROXY: Response: 200, length: 24478840 Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/326220" Jun 11 19:48:10 volumio volumio[1050]: info: Jun 11 19:48:10 volumio volumio[1050]: ---------------------------- MPD announces system playlist update Jun 11 19:48:10 volumio volumio[1050]: STREAMING PROXY: Client dropped request, destroying Jun 11 19:48:10 volumio volumio[1050]: info: Ignoring MPD Status Update Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/326220" took 2 milliseconds Jun 11 19:48:10 volumio volumio[1050]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 11 19:48:10 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand play Jun 11 19:48:10 volumio volumio[1050]: info: ------------------------------ 3ms Jun 11 19:48:10 volumio volumio[1050]: info: sendMpdCommand play took 2 milliseconds Jun 11 19:48:10 volumio volumio[1050]: STREAMING PROXY: Handling url /?data=qobuz://song/326220 Jun 11 19:48:10 volumio volumio[1050]: info: Executing endpoint getStreamUrlqobuz Jun 11 19:48:10 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 11 19:48:11 volumio volumio[1050]: info: getStreamUrl took 395 milliseconds Jun 11 19:48:11 volumio volumio[1050]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=1889012&eid=326220&fmt=6&profile=raw&app_id=539451548&cid=1848830&etsp=1749667691&hmac=t59uACYAt3Ta0qPKPbupguCzXEM Jun 11 19:48:11 volumio volumio[1050]: STREAMING PROXY: Response: 200, length: 24478840 Jun 11 19:48:11 volumio volumio[1050]: info: Jun 11 19:48:11 volumio volumio[1050]: ---------------------------- MPD announces state update: player Jun 11 19:48:11 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:11 volumio volumio[1050]: info: Jun 11 19:48:11 volumio volumio[1050]: ---------------------------- MPD announces state update: player Jun 11 19:48:11 volumio volumio[1050]: info: sendMpdCommand status took 4 milliseconds Jun 11 19:48:11 volumio volumio[1050]: info: ControllerMpd::getState Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand status Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 11 19:48:11 volumio volumio[1050]: info: sendMpdCommand status took 2 milliseconds Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::parseState Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 11 19:48:11 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! Jun 11 19:48:11 volumio volumio[1050]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 11 19:48:11 volumio volumio[1050]: info: sendMpdCommand playlistinfo took 3 milliseconds Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::parseTrackInfo Jun 11 19:48:11 volumio volumio[1050]: verbose: ControllerMpd::parseTrackInfo Jun 11 19:48:11 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:48:11 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:11 volumio volumio[1050]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":233,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"326220","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/326220","trackType":"qobuz"} Jun 11 19:48:11 volumio volumio[1050]: verbose: CURRENT POSITION 2 Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::syncState stateService play Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:48:11 volumio volumio[1050]: info: ControllerMpd::pushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::servicePushState Jun 11 19:48:11 volumio volumio[1050]: info: CorePlayQueue::getTrack 2 Jun 11 19:48:11 volumio volumio[1050]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":233,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"326220","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/326220","trackType":"qobuz"} Jun 11 19:48:11 volumio volumio[1050]: verbose: CURRENT POSITION 2 Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::syncState stateService play Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:48:11 volumio volumio[1050]: info: Received an update from plugin. extracting info from payload Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:11 volumio volumio[1050]: info: CoreStateMachine::pushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::volumioPushState Jun 11 19:48:11 volumio volumio[1050]: info: CoreCommandRouter::volumioGetState Jun 11 19:48:11 volumio volumio[1050]: info: ------------------------------ 39ms Jun 11 19:48:11 volumio volumio[1050]: info: ------------------------------ 67ms Jun 11 19:48:12 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 11 19:48:13 volumio volumio[1050]: STREAMING PROXY: Client dropped request, destroying Jun 11 19:48:16 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 11 19:48:19 volumio volumio[1050]: info: Disabling MyMusic plugin upnp Jun 11 19:48:19 volumio sudo[4662]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jun 11 19:48:19 volumio sudo[4662]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 19:48:19 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Jun 11 19:48:19 volumio volumio[1050]: error: Upnp client error: Error: This socket has been ended by the other party Jun 11 19:48:20 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jun 11 19:48:21 volumio volumio[1050]: info: Enabling MyMusic plugin upnp Jun 11 19:48:21 volumio volumio[1050]: info: Enabling plugin upnp Jun 11 19:48:21 volumio volumio[1050]: info: Loading plugin "upnp"... Jun 11 19:48:21 volumio volumio[1050]: info: [1749664101352] Starting Upmpd Daemon Jun 11 19:48:21 volumio volumio[1050]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 11 19:48:21 volumio volumio[1050]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 19:48:21 volumio volumio[1050]: Error: listen EADDRINUSE: address already in use :::6599 Jun 11 19:48:21 volumio volumio[1050]: at Server.setupListenHandle [as _listen2] (net.js:1318:16) Jun 11 19:48:21 volumio volumio[1050]: at listenInCluster (net.js:1366:12) Jun 11 19:48:21 volumio volumio[1050]: at Server.listen (net.js:1452:7) Jun 11 19:48:21 volumio volumio[1050]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Jun 11 19:48:21 volumio volumio[1050]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Jun 11 19:48:21 volumio volumio[1050]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 11 19:48:21 volumio volumio[1050]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 11 19:48:21 volumio volumio[1050]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Jun 11 19:48:21 volumio volumio[1050]: code: 'EADDRINUSE', Jun 11 19:48:21 volumio volumio[1050]: errno: -98, Jun 11 19:48:21 volumio volumio[1050]: syscall: 'listen', Jun 11 19:48:21 volumio volumio[1050]: address: '::', Jun 11 19:48:21 volumio volumio[1050]: port: 6599 Jun 11 19:48:21 volumio volumio[1050]: } Jun 11 19:48:21 volumio volumio[1050]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 19:48:21 volumio sudo[4687]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-11 19:47 Jun 11 19:48:21 volumio sudo[4687]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"