-- Logs begin at Sun 2024-04-14 12:32:30 CEST, end at Sun 2024-04-14 12:43:39 CEST. -- Apr 14 12:42:01 volumio volumio[2234]: info: Tunnel connection is inactive, restarting it Apr 14 12:42:01 volumio volumio[2234]: info: Starting Tunnel 1 Apr 14 12:42:01 volumio volumio[2234]: info: Starting Tunnel Connection Checker Apr 14 12:42:01 volumio sudo[2751]: volumio : unable to resolve host volumio Apr 14 12:42:01 volumio sudo[2751]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:01 volumio sudo[2751]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Apr 14 12:42:01 volumio sudo[2751]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:01 volumio autossh[2575]: received signal to exit (15) Apr 14 12:42:01 volumio systemd[1]: Stopping MyVolumio SSH Tunnel... Apr 14 12:42:01 volumio systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Apr 14 12:42:01 volumio systemd[1]: sshtunnel.service: Succeeded. Apr 14 12:42:01 volumio systemd[1]: Stopped MyVolumio SSH Tunnel. Apr 14 12:42:01 volumio systemd[1]: Started MyVolumio SSH Tunnel. Apr 14 12:42:01 volumio sudo[2751]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:01 volumio volumio[2234]: info: Remote SSH Started Apr 14 12:42:01 volumio autossh[2754]: port set to 0, monitoring disabled Apr 14 12:42:01 volumio autossh[2754]: starting ssh (count 1) Apr 14 12:42:01 volumio autossh[2754]: ssh child pid is 2757 Apr 14 12:42:02 volumio volumio[2234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 14 12:42:02 volumio volumio[2234]: info: CoreCommandRouter::volumioGetState Apr 14 12:42:02 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:02 volumio volumiossh-tunnel[2753]: Warning: Permanently added '[eu4.myvolumio.org]:2222,[167.172.103.77]:2222' (RSA) to the list of known hosts. Apr 14 12:42:23 volumio volumio[2234]: info: CoreCommandRouter::volumioGetState Apr 14 12:42:23 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:24 volumio volumio[2234]: info: CoreCommandRouter::volumioPlay Apr 14 12:42:24 volumio volumio[2234]: info: CoreStateMachine::play index undefined Apr 14 12:42:24 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 12:42:24 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:24 volumio volumio[2234]: info: CoreStateMachine::startPlaybackTimer Apr 14 12:42:24 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:24 volumio volumio[2234]: info: [1713091344611] ControllerTidal::clearAddPlayTrack Apr 14 12:42:24 volumio volumio[2234]: info: Getting stream with soundQuality HI_RES Apr 14 12:42:24 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 12:42:24 volumio volumio[2234]: info: sendMpdCommand stop took 4 milliseconds Apr 14 12:42:24 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand clear Apr 14 12:42:24 volumio volumio[2234]: info: Apr 14 12:42:24 volumio volumio[2234]: ---------------------------- MPD announces system playlist update Apr 14 12:42:24 volumio volumio[2234]: info: Ignoring MPD Status Update Apr 14 12:42:24 volumio volumio[2234]: info: sendMpdCommand clear took 6 milliseconds Apr 14 12:42:24 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/205573155&soundQuality=HI_RES" Apr 14 12:42:24 volumio volumio[2234]: error: updateQueue error: null Apr 14 12:42:24 volumio volumio[2234]: info: Apr 14 12:42:24 volumio volumio[2234]: ---------------------------- MPD announces system playlist update Apr 14 12:42:24 volumio volumio[2234]: info: Ignoring MPD Status Update Apr 14 12:42:24 volumio volumio[2234]: info: ------------------------------ 12ms Apr 14 12:42:24 volumio volumio[2234]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/205573155&soundQuality=HI_RES" took 7 milliseconds Apr 14 12:42:24 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 14 12:42:24 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand play Apr 14 12:42:24 volumio volumio[2234]: info: ------------------------------ 11ms Apr 14 12:42:24 volumio volumio[2234]: info: sendMpdCommand play took 7 milliseconds Apr 14 12:42:24 volumio volumio[2234]: STREAMING PROXY: Handling url /?data=tidal://song/205573155&soundQuality=HI_RES Apr 14 12:42:24 volumio volumio[2234]: info: Executing endpoint getStreamUrltidal Apr 14 12:42:24 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI Apr 14 12:42:25 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:25 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:25 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:25 volumio volumio[2234]: info: getStreamUrl took 777 milliseconds Apr 14 12:42:25 volumio volumio[2234]: STREAMING PROXY: Got real url: http://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKRInMThhMWM1ZDExYTM0Y2QzN2JlOTZkNmU3Zjc3ODdiMzhfNjIubXA0/0.flac?token=1713094935~YWRjMzYwYjk2YTFjYzAyNDBlMjE0NmJiNDg3NTU2ZTI4YmIwMTZhZQ== Apr 14 12:42:25 volumio volumio[2234]: STREAMING PROXY: Response: 200, length: 41511440 Apr 14 12:42:25 volumio volumio[2234]: info: Apr 14 12:42:25 volumio volumio[2234]: ---------------------------- MPD announces state update: player Apr 14 12:42:25 volumio volumio[2234]: info: ControllerMpd::getState Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand status Apr 14 12:42:25 volumio volumio[2234]: info: Apr 14 12:42:25 volumio volumio[2234]: ---------------------------- MPD announces state update: player Apr 14 12:42:25 volumio volumio[2234]: info: sendMpdCommand status took 26 milliseconds Apr 14 12:42:25 volumio volumio[2234]: info: ControllerMpd::getState Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand status Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::parseState Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 12:42:25 volumio volumio[2234]: info: sendMpdCommand status took 10 milliseconds Apr 14 12:42:25 volumio volumio[2234]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::parseState Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::parseTrackInfo Apr 14 12:42:25 volumio volumio[2234]: info: ControllerMpd::pushState Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::servicePushState Apr 14 12:42:25 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:25 volumio volumio[2234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"205573155&soundQuality=HI_RES","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/205573155&soundQuality=HI_RES","trackType":"tidal"} Apr 14 12:42:25 volumio volumio[2234]: verbose: CURRENT POSITION 0 Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::syncState stateService play Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::syncState currentStatus stop Apr 14 12:42:25 volumio volumio[2234]: info: ------------------------------ 63ms Apr 14 12:42:25 volumio volumio[2234]: info: sendMpdCommand playlistinfo took 16 milliseconds Apr 14 12:42:25 volumio volumio[2234]: verbose: ControllerMpd::parseTrackInfo Apr 14 12:42:25 volumio volumio[2234]: info: ControllerMpd::pushState Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::servicePushState Apr 14 12:42:25 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:25 volumio volumio[2234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":225,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"205573155&soundQuality=HI_RES","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/205573155&soundQuality=HI_RES","trackType":"tidal"} Apr 14 12:42:25 volumio volumio[2234]: verbose: CURRENT POSITION 0 Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::syncState stateService play Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::syncState currentStatus play Apr 14 12:42:25 volumio volumio[2234]: info: Received an update from plugin. extracting info from payload Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:25 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:25 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:25 volumio volumio[2234]: info: ------------------------------ 146ms Apr 14 12:42:25 volumio volumio[2234]: info: [LastFM] Current track has sufficient metadata: title (Easy On Me) and artist (Adele) passed on explicitly Apr 14 12:42:26 volumio volumio[2234]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Easy On ME","url":"https://www.last.fm/music/Adele/_/Easy+On+ME","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"773707","playcount":"8979864","artist":{"name":"Adele","mbid":"cc2c9c3c-b7bc-4b8b-84d8-4fbd8779e493","url":"https://www.last.fm/music/Adele"},"userplaycount":"11","userloved":"0","toptags":{"tag":[{"name":"2021","url":"https://www.last.fm/tag/2021"},{"name":"pop","url":"https://www.last.fm/tag/pop"},{"name":"Adele","url":"https://www.last.fm/tag/Adele"},{"name":"soul","url":"https://www.last.fm/tag/soul"},{"name":"piano","url":"https://www.last.fm/tag/piano"}]},"wiki":{"published":"14 Oct 2021, 20:52","summary":"\"Easy on Me\" is a plea to take it easy with someone who hasn't had the same chance to make their own decisions or experience the world. The lyrics imply that the singer was unable to explore the world around them due to their circumstances and had to go with the choices that were made for them. The singer is asking for the other person to not be too hard on them and to accept that they were still learning. The bridge hints at how the singer has had good intentions and hopeful outcomes Read more on Last.fm.","content":"\"Easy on Me\" is a plea to take it easy with someone who hasn't had the same chance to make their own decisions or experience the world. The lyrics imply that the singer was unable to explore the world around them due to their circumstances and had to go with the choices that were made for them. The singer is asking for the other person to not be too hard on them and to accept that they were still learning. The bridge hints at how the singer has had good intentions and hopeful outcomes, and though it may not show right now, they still want to be taken into account. Read more on Last.fm. User-contributed text is available under the Creative Commons By-SA License; additional terms may apply."}}} Apr 14 12:42:27 volumio volumio[2234]: STREAMING PROXY: Client dropped request, destroying Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::volumioNext Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::next Apr 14 12:42:30 volumio volumio[2234]: info: [1713091350272] ControllerTidal::next Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::next Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::stop Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::stPlaybackTimer Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::updateTrackBlock Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrackBlock Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::serviceStop Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 0 Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::serviceStop Apr 14 12:42:30 volumio volumio[2234]: info: [1713091350307] ControllerTidal::stop Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 14 12:42:30 volumio volumio[2234]: info: ControllerMpd::stop Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 12:42:30 volumio volumio[2234]: info: Apr 14 12:42:30 volumio volumio[2234]: ---------------------------- MPD announces state update: player Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand stop took 38 milliseconds Apr 14 12:42:30 volumio volumio[2234]: info: ControllerMpd::getState Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand status Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::play index undefined Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::startPlaybackTimer Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:30 volumio volumio[2234]: info: [1713091350358] ControllerTidal::clearAddPlayTrack Apr 14 12:42:30 volumio volumio[2234]: info: Getting stream with soundQuality LOSSLESS Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand stop Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::updateTrackBlock Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrackBlock Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand status took 15 milliseconds Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand stop took 6 milliseconds Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::parseState Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand clear Apr 14 12:42:30 volumio volumio[2234]: info: Apr 14 12:42:30 volumio volumio[2234]: ---------------------------- MPD announces system playlist update Apr 14 12:42:30 volumio volumio[2234]: info: Ignoring MPD Status Update Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand clear took 10 milliseconds Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::parseTrackInfo Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/5267737&soundQuality=LOSSLESS" Apr 14 12:42:30 volumio volumio[2234]: info: ControllerMpd::pushState Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::servicePushState Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:30 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:30 volumio volumio[2234]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received mpd Apr 14 12:42:30 volumio volumio[2234]: info: ------------------------------ 75ms Apr 14 12:42:30 volumio volumio[2234]: error: updateQueue error: null Apr 14 12:42:30 volumio volumio[2234]: info: Apr 14 12:42:30 volumio volumio[2234]: ---------------------------- MPD announces system playlist update Apr 14 12:42:30 volumio volumio[2234]: info: Ignoring MPD Status Update Apr 14 12:42:30 volumio volumio[2234]: info: ------------------------------ 52ms Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/5267737&soundQuality=LOSSLESS" took 42 milliseconds Apr 14 12:42:30 volumio volumio[2234]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 14 12:42:30 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand play Apr 14 12:42:30 volumio volumio[2234]: STREAMING PROXY: Handling url /?data=tidal://song/5267737&soundQuality=LOSSLESS Apr 14 12:42:30 volumio volumio[2234]: info: ------------------------------ 33ms Apr 14 12:42:30 volumio volumio[2234]: info: sendMpdCommand play took 29 milliseconds Apr 14 12:42:30 volumio volumio[2234]: info: Executing endpoint getStreamUrltidal Apr 14 12:42:30 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI Apr 14 12:42:31 volumio volumio[2234]: info: getStreamUrl took 802 milliseconds Apr 14 12:42:31 volumio volumio[2234]: STREAMING PROXY: Got real url: http://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKRInNDUyZWRiNDFlMGUyZjdhMjY4NDc5Y2JiNzc1YjRjNGVfNjEubXA0/0.flac?token=1713094939~NjU3MjZjZWQ2OTI4ODk2NzU0OTZmMGY0ZmYzNTFlZTNkNzFlMmNkNw== Apr 14 12:42:31 volumio volumio[2234]: STREAMING PROXY: Response: 200, length: 29314692 Apr 14 12:42:31 volumio volumio[2234]: info: Apr 14 12:42:31 volumio volumio[2234]: ---------------------------- MPD announces state update: player Apr 14 12:42:31 volumio volumio[2234]: info: ControllerMpd::getState Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand status Apr 14 12:42:31 volumio volumio[2234]: info: Apr 14 12:42:31 volumio volumio[2234]: ---------------------------- MPD announces state update: player Apr 14 12:42:31 volumio volumio[2234]: info: sendMpdCommand status took 5 milliseconds Apr 14 12:42:31 volumio volumio[2234]: info: ControllerMpd::getState Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand status Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::parseState Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 12:42:31 volumio volumio[2234]: info: sendMpdCommand status took 6 milliseconds Apr 14 12:42:31 volumio volumio[2234]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::parseState Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::parseTrackInfo Apr 14 12:42:31 volumio volumio[2234]: info: ControllerMpd::pushState Apr 14 12:42:31 volumio volumio[2234]: info: CoreCommandRouter::servicePushState Apr 14 12:42:31 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:31 volumio volumio[2234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":243,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"5267737&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/5267737&soundQuality=LOSSLESS","trackType":"tidal"} Apr 14 12:42:31 volumio volumio[2234]: verbose: CURRENT POSITION 1 Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::syncState stateService play Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::syncState currentStatus stop Apr 14 12:42:31 volumio volumio[2234]: info: ------------------------------ 32ms Apr 14 12:42:31 volumio volumio[2234]: info: sendMpdCommand playlistinfo took 12 milliseconds Apr 14 12:42:31 volumio volumio[2234]: verbose: ControllerMpd::parseTrackInfo Apr 14 12:42:31 volumio volumio[2234]: info: ControllerMpd::pushState Apr 14 12:42:31 volumio volumio[2234]: info: CoreCommandRouter::servicePushState Apr 14 12:42:31 volumio volumio[2234]: info: CorePlayQueue::getTrack 1 Apr 14 12:42:31 volumio volumio[2234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":243,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"5267737&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/5267737&soundQuality=LOSSLESS","trackType":"tidal"} Apr 14 12:42:31 volumio volumio[2234]: verbose: CURRENT POSITION 1 Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::syncState stateService play Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::syncState currentStatus play Apr 14 12:42:31 volumio volumio[2234]: info: Received an update from plugin. extracting info from payload Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:31 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 12:42:31 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:31 volumio volumio[2234]: info: CoreStateMachine::pushState Apr 14 12:42:31 volumio volumio[2234]: info: CoreCommandRouter::volumioPushState Apr 14 12:42:31 volumio volumio[2234]: info: ------------------------------ 131ms Apr 14 12:42:31 volumio volumio[2234]: info: [LastFM] Current track has sufficient metadata: title (Set Fire to the Rain) and artist (Adele) passed on explicitly Apr 14 12:42:31 volumio volumio[2234]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Set Fire to the Rain","mbid":"d1e0a99e-1894-457b-ba6a-985eeef4d0c4","url":"https://www.last.fm/music/Adele/_/Set+Fire+to+the+Rain","duration":"241000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1541583","playcount":"15679210","artist":{"name":"Adele","mbid":"cc2c9c3c-b7bc-4b8b-84d8-4fbd8779e493","url":"https://www.last.fm/music/Adele"},"album":{"@":{"position":"5"},"artist":"Adele","title":"21","mbid":"c45e0e0e-48c9-4441-aac3-2f2b34202d3c","url":"https://www.last.fm/music/Adele/21","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/75075bd01c96465e54fc250b22f83296.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/75075bd01c96465e54fc250b22f83296.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/75075bd01c96465e54fc250b22f83296.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/75075bd01c96465e54fc250b22f83296.png","@":{"size":"extralarge"}}]},"userplaycount":"8","userloved":"0","toptags":{"tag":[{"name":"soul","url":"https://www.last.fm/tag/soul"},{"name":"Adele","url":"https://www.last.fm/tag/Adele"},{"name":"female vocalists","url":"https://www.last.fm/tag/female+vocalists"},{"name":"pop","url":"https://www.last.fm/tag/pop"},{"name":"british","url":"https://www.last.fm/tag/british"}]},"wiki":{"published":"13 Aug 2011, 15:46","summary":"\"Set Fire to the Rain\" is a song performed by english singer-songwriter Adele, released as the third single from her studio album, 21. The song talks about a relationship coming to an end. Girl meets guy, he is wonderful and she falls really quickly. He tells her all of these amazing things, but really they were all a lie and now she is left with a broken heart. He continually tries to play games with her and no matter hard she fights, she will never win. Nothing she can do will fix the relationship. Read more on Last.fm.","content":"\"Set Fire to the Rain\" is a song performed by english singer-songwriter Adele, released as the third single from her studio album, 21. The song talks about a relationship coming to an end. Girl meets guy, he is wonderful and she falls really quickly. He tells her all of these amazing things, but really they were all a lie and now she is left with a broken heart. He continually tries to play games with her and no matter hard she fights, she will never win. Nothing she can do will fix the relationship. As hard as she doesn’t want to let him go, she breaks it off in order to save herself for further heartbreak. The pain of breaking off a relationship with someone who means so much but is two-sided and not good to be with. The title is an allusion to James Taylor’s Fire and Rain, but Adele approaches the same themes with a thug-feminist perspective. In the US, the song hit #1, becoming her third consecutive number one from the album. She wouldn’t reach such heights again until her comeback single Hello debuted at number one with a shocking 1.12 million copies sold in one week – the largest ever recorded in the US. Read more on Last.fm. User-contributed text is available under the Creative Commons By-SA License; additional terms may apply."}}} Apr 14 12:42:32 volumio volumio[2234]: error: Failed request for metavolumio API Apr 14 12:42:32 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:32 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:32 volumio volumio[2234]: STREAMING PROXY: Client dropped request, destroying Apr 14 12:42:32 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:32 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:32 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:32 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:35 volumio kernel: perf: interrupt took too long (5119 > 5101), lowering kernel.perf_event_max_sample_rate to 39000 Apr 14 12:42:39 volumio volumio[2234]: error: Failed request for metavolumio API Apr 14 12:42:41 volumio volumio[2234]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 14 12:42:41 volumio volumio[2234]: /bin/cat: /sys/class/net/wlan0/flags: No such file or directory Apr 14 12:42:41 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 14 12:42:41 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Apr 14 12:42:41 volumio sudo[2810]: volumio : unable to resolve host volumio Apr 14 12:42:41 volumio sudo[2810]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2810]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Apr 14 12:42:42 volumio sudo[2810]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2810]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio sudo[2815]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2815]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2815]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Apr 14 12:42:42 volumio sudo[2815]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2823]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2823]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2823]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Apr 14 12:42:42 volumio sudo[2823]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2815]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio sudo[2830]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2830]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2830]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Apr 14 12:42:42 volumio sudo[2830]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2823]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio sudo[2842]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2842]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2842]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 14 12:42:42 volumio sudo[2842]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2842]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio sudo[2848]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2848]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2830]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio sudo[2848]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 14 12:42:42 volumio sudo[2848]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Apr 14 12:42:42 volumio sudo[2848]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Apr 14 12:42:42 volumio sudo[2856]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2856]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2856]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 14 12:42:42 volumio sudo[2856]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2856]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio volumio[2234]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Apr 14 12:42:42 volumio volumio[2234]: sudo: unable to resolve host volumio: System error Apr 14 12:42:42 volumio volumio[2234]: wlan0 Interface doesn't support scanning. Apr 14 12:42:42 volumio volumio[2234]: info: Cannot use regular scanning, forcing with ap-force Apr 14 12:42:42 volumio sudo[2861]: volumio : unable to resolve host volumio Apr 14 12:42:42 volumio sudo[2861]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:42:42 volumio sudo[2861]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Apr 14 12:42:42 volumio sudo[2861]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 12:42:42 volumio sudo[2861]: pam_unix(sudo:session): session closed for user root Apr 14 12:42:42 volumio volumio[2234]: sudo: unable to resolve host volumio: System error Apr 14 12:42:42 volumio volumio[2234]: command failed: No such device (-19) Apr 14 12:42:42 volumio volumio[2234]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Apr 14 12:42:42 volumio volumio[2234]: sudo: unable to resolve host volumio: System error Apr 14 12:42:42 volumio volumio[2234]: command failed: No such device (-19) Apr 14 12:42:53 volumio volumio[2234]: info: CoreCommandRouter::volumioGetState Apr 14 12:42:54 volumio volumio[2234]: info: CoreCommandRouter::volumioGetQueue Apr 14 12:42:54 volumio volumio[2234]: info: CoreStateMachine::getQueue Apr 14 12:42:54 volumio volumio[2234]: info: CorePlayQueue::getQueue Apr 14 12:42:55 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:55 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:55 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:55 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:42:55 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:42:55 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:00 volumio ntpd[747]: 193.25.222.136 local addr 192.168.1.91 -> Apr 14 12:43:04 volumio volumio[2234]: info: CoreCommandRouter::volumioGetState Apr 14 12:43:06 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:06 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:06 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:06 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:06 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:06 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:09 volumio ntpd[747]: 162.159.200.1 local addr 192.168.1.91 -> Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Apr 14 12:43:11 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 14 12:43:22 volumio volumio[2234]: info: CoreCommandRouter::volumioGetState Apr 14 12:43:24 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:24 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:24 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:24 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:24 volumio volumio[2234]: info: Executing endpoint metavolumio Apr 14 12:43:24 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 14 12:43:30 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 14 12:43:30 volumio volumio[2234]: info: Preload queue cleared Apr 14 12:43:33 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 14 12:43:34 volumio volumio[2234]: info: Preload queue cleared Apr 14 12:43:36 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 14 12:43:36 volumio volumio[2234]: info: Preload queue cleared Apr 14 12:43:38 volumio volumio[2234]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 14 12:43:38 volumio volumio[2234]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 12:43:38 volumio volumio[2234]: TypeError: Cannot read property 'length' of undefined Apr 14 12:43:38 volumio volumio[2234]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Apr 14 12:43:38 volumio volumio[2234]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Apr 14 12:43:38 volumio volumio[2234]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Apr 14 12:43:38 volumio volumio[2234]: at Parser.emit (events.js:400:28) Apr 14 12:43:38 volumio volumio[2234]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Apr 14 12:43:38 volumio volumio[2234]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Apr 14 12:43:38 volumio volumio[2234]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Apr 14 12:43:38 volumio volumio[2234]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Apr 14 12:43:38 volumio volumio[2234]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Apr 14 12:43:38 volumio volumio[2234]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Apr 14 12:43:38 volumio volumio[2234]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Apr 14 12:43:38 volumio volumio[2234]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Apr 14 12:43:38 volumio volumio[2234]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Apr 14 12:43:38 volumio volumio[2234]: at IncomingMessage.emit (events.js:412:35) Apr 14 12:43:38 volumio volumio[2234]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 14 12:43:38 volumio volumio[2234]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 14 12:43:38 volumio volumio[2234]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 12:43:39 volumio sudo[2919]: volumio : unable to resolve host volumio Apr 14 12:43:39 volumio sudo[2919]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Apr 14 12:43:39 volumio sudo[2919]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 12:42 Apr 14 12:43:39 volumio sudo[2919]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7b9cb4a8b52fb7148a38d6ac651c1c29e09bb92c" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="b1dcc17f6d31bf91f0abd3c3fa57506d1e0d2b6b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 01 Mar 2024 08:52:33 PM CET" VOLUMIO_VERSION="3.634" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="93edfc70711724967af109c0a39fa069"