-- Logs begin at Sat 2024-04-06 15:10:38 UTC, end at Sat 2024-04-06 16:07:45 UTC. -- Apr 06 16:06:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2250. Apr 06 16:06:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:00 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:00 volumio go-librespot[11629]: Librespot-go daemon starting... Apr 06 16:06:00 volumio go-librespot[11629]: time="2024-04-06T16:06:00Z" level=info msg="generated new device id: 170883059b2246dfd7d426401f28b5d1f170a7a6" Apr 06 16:06:00 volumio go-librespot[11629]: time="2024-04-06T16:06:00Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:00 volumio go-librespot[11629]: time="2024-04-06T16:06:00Z" level=debug msg="obtained new client token: AABSU1At0aOU72UN9x+LdZh5GeiDwo6qh1x4+Z44tGSp7aBw/93bU8sz89dWuOHJtkr/04bAc3NwMV4d+yqZEtgbOpLPqS9p01yo5cWRrT2/1vh6zUNiVc/sHF7L2WZRvMJ7l3sxVoC55zTRpc/V2+VFEiDZqHROifA7HU0mfbn5MaUeO4HmGzmzLmJbzpox/pkTazDJrnjXnx9b3qOni5WJcFsA7JDDBywrY4BdcAJQvFvpiYMckwwcKInXmH8=" Apr 06 16:06:00 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:00 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:06:00 volumio go-librespot[11629]: time="2024-04-06T16:06:00Z" level=debug msg="new websocket client" Apr 06 16:06:01 volumio go-librespot[11629]: time="2024-04-06T16:06:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:01 volumio go-librespot[11629]: time="2024-04-06T16:06:01Z" level=debug msg="completed keyexchange" Apr 06 16:06:01 volumio go-librespot[11629]: time="2024-04-06T16:06:01Z" level=debug msg="completed challenge" Apr 06 16:06:01 volumio go-librespot[11629]: time="2024-04-06T16:06:01Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:01 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: mixer Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: output Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: mixer Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: output Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: mixer Apr 06 16:06:01 volumio volumio[775]: info: Apr 06 16:06:01 volumio volumio[775]: ---------------------------- MPD announces state update: output Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 10 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 11 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 8 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 8 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 18 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 17 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 16 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 16 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 15 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 15 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 15 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand clearerror took 14 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 06 16:06:01 volumio volumio[775]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":22045,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:01 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:01 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:01 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:01 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 55ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 55ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 55ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 53ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 54ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 54ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 55ms Apr 06 16:06:01 volumio volumio[775]: info: ------------------------------ 55ms Apr 06 16:06:03 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:06:03 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:03 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:06:03 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 747) Apr 06 16:06:03 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:04 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:04 volumio volumio[775]: info: Apr 06 16:06:04 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:04 volumio volumio[775]: info: Apr 06 16:06:04 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:04 volumio volumio[775]: info: Apr 06 16:06:04 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand status took 5 milliseconds Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand status took 4 milliseconds Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand status took 4 milliseconds Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand clearerror took 6 milliseconds Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand clearerror took 6 milliseconds Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand clearerror took 5 milliseconds Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 06 16:06:04 volumio volumio[775]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:04 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:04 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:04 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:04 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:04 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus play Apr 06 16:06:04 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:04 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:04 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:04 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:04 volumio volumio[775]: info: ------------------------------ 19ms Apr 06 16:06:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2251. Apr 06 16:06:04 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:04 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:04 volumio go-librespot[11643]: Librespot-go daemon starting... Apr 06 16:06:04 volumio go-librespot[11643]: time="2024-04-06T16:06:04Z" level=info msg="generated new device id: 20274407e92cc06f495c12271eb199f9197b0ae6" Apr 06 16:06:04 volumio go-librespot[11643]: time="2024-04-06T16:06:04Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:05 volumio go-librespot[11643]: time="2024-04-06T16:06:05Z" level=debug msg="obtained new client token: AAC9SWM2NfAowzbRqFUZozttirADGc+2O0eMGxNHdY4BiLnxh8jPnymyla6YRGvPqkRubGu85R192gAdQ3XrqoIfMSTlsGxNIjZYdqo6R3xaoD7lu6TAQH//fEIlKVEwei7KIiS2jADNaqFXGG81HEbofZmRtQZeXYc45LefE6uar0C9NFlAFCXxq9ylbFCkTpSYSvE7y8yTx4hK+OHx56070sbQzJvm34GQ1embDbrClkvjk7hstt1KQ1YK" Apr 06 16:06:05 volumio go-librespot[11643]: time="2024-04-06T16:06:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:05 volumio go-librespot[11643]: time="2024-04-06T16:06:05Z" level=debug msg="completed keyexchange" Apr 06 16:06:05 volumio go-librespot[11643]: time="2024-04-06T16:06:05Z" level=debug msg="completed challenge" Apr 06 16:06:05 volumio go-librespot[11643]: time="2024-04-06T16:06:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:07 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 6 Apr 06 16:06:07 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:07 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 06 16:06:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 06 16:06:07 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:07 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:09 volumio sudo[11652]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 06 16:06:09 volumio sudo[11652]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:09 volumio sudo[11652]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:09 volumio sudo[11655]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 06 16:06:09 volumio sudo[11655]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2252. Apr 06 16:06:09 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:09 volumio sudo[11655]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:09 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:09 volumio go-librespot[11657]: Librespot-go daemon starting... Apr 06 16:06:09 volumio go-librespot[11657]: time="2024-04-06T16:06:09Z" level=info msg="generated new device id: 62a425ebfbadee9336caf00762d7338ed5146823" Apr 06 16:06:09 volumio go-librespot[11657]: time="2024-04-06T16:06:09Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:09 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 7 Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::volumioGetVisibleSources Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:09 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 06 16:06:09 volumio go-librespot[11657]: time="2024-04-06T16:06:09Z" level=debug msg="obtained new client token: AABHjcabybPlnQZgybkFuBnQAzpCaAK4Ki+fKGEkl2jMGL8mYftL47A/HtYHN8uJMs4o6rNXVV46TlOVjQ0fzMUjsbYFTC2LQ6cK+xJg3VEygFNRgGj771OrhYja2QKFL7aQKCP2qnquirff26JHhKlCLNWOWWFcSYS7InpBEpKBS1LvHpR/YZmeIUp2MiYW84ftxnKDTz1bDRrKkfHRD/uaI6hOvB4uacJHNbF6VK6MxmGUGpcXQMpCVX3Uq5Y=" Apr 06 16:06:09 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:09 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:09 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:09 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:09 volumio volumio[775]: info: Listing playlists Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 06 16:06:09 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 06 16:06:09 volumio go-librespot[11657]: time="2024-04-06T16:06:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:09 volumio go-librespot[11657]: time="2024-04-06T16:06:09Z" level=debug msg="completed keyexchange" Apr 06 16:06:10 volumio go-librespot[11657]: time="2024-04-06T16:06:10Z" level=debug msg="completed challenge" Apr 06 16:06:10 volumio go-librespot[11657]: time="2024-04-06T16:06:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:10 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:10 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:11 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:11 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:11 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:11 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:11 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:11 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:11 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:11 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:12 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:12 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:12 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:12 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:12 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:12 volumio volumio[775]: info: CoreCommandRouter::volumioGetQueue Apr 06 16:06:12 volumio volumio[775]: info: CoreStateMachine::getQueue Apr 06 16:06:12 volumio volumio[775]: info: CorePlayQueue::getQueue Apr 06 16:06:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2253. Apr 06 16:06:13 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:13 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:13 volumio go-librespot[11665]: Librespot-go daemon starting... Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=info msg="generated new device id: 9f9fa5fab448c70a31b9fef31a8d191afdf630ff" Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=debug msg="obtained new client token: AADjf2EYiChdA7u+bmrPzyTzOEqGnrdA2aD3KN4e9qZjoz7yc8xk6m4d58MZ2VlF5O7J0ilvWKK4zhF4T7BjELuxW3SIj1QcZ/gmL2T2NQ/aoKh7svZPuQqaNZItdJslmD0m6ZeCjJCH8Fn74m8NEBWHfwl/Vu+CXUJTNc559fHl4/rsww3jH+Ol/c1OC45rGNkYYeNsQhY21EEcgW0p7eCwG5dmlkV/U0wdPyraRkXqqEFf1ioZuVn0B02cR28=" Apr 06 16:06:13 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=debug msg="new websocket client" Apr 06 16:06:13 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:13 volumio go-librespot[11665]: time="2024-04-06T16:06:13Z" level=debug msg="completed keyexchange" Apr 06 16:06:14 volumio go-librespot[11665]: time="2024-04-06T16:06:14Z" level=debug msg="completed challenge" Apr 06 16:06:14 volumio go-librespot[11665]: time="2024-04-06T16:06:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:14 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:06:15 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 06 16:06:15 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 06 16:06:16 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:06:16 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:16 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:06:16 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 748) Apr 06 16:06:16 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 06 16:06:16 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:16 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:17 volumio sudo[11674]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 06 16:06:17 volumio sudo[11674]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:17 volumio sudo[11674]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:17 volumio sudo[11677]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 06 16:06:17 volumio sudo[11677]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:17 volumio sudo[11677]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:17 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:17 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:17 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 7 Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::volumioGetVisibleSources Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:17 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 06 16:06:17 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:17 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:17 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:17 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:17 volumio volumio[775]: info: Listing playlists Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 06 16:06:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2254. Apr 06 16:06:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:17 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 06 16:06:17 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:17 volumio go-librespot[11679]: Librespot-go daemon starting... Apr 06 16:06:17 volumio go-librespot[11679]: time="2024-04-06T16:06:17Z" level=info msg="generated new device id: 3bfcefd6c9577912cda1703a11aac76c4f29ff5e" Apr 06 16:06:17 volumio go-librespot[11679]: time="2024-04-06T16:06:17Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:17 volumio go-librespot[11679]: time="2024-04-06T16:06:17Z" level=debug msg="obtained new client token: AAAJZm449QYKpsHVpP9ZU/f90pj7WZGKa39EEVL3nQ5PAB08RpMo2wXY6BsHFaeCyLrmKB6z4hOmU3oMjPtJMs1te8epvX79ajCIN2Da0cWZR/EQtYduOTP00I8qeM2cPu/NQQl26cWKc4KqQi7Y0D8CiZFQl8bIF+0kpAc0XOcVjY12i9Ecwvo3PFChaKm1BeqGDhEsxlto/LkOFkwvZao5s+9uIXhn2noMfrjxWBAPaT+ADoDHEE5dru9oeJ0=" Apr 06 16:06:18 volumio go-librespot[11679]: time="2024-04-06T16:06:18Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:18 volumio go-librespot[11679]: time="2024-04-06T16:06:18Z" level=debug msg="completed keyexchange" Apr 06 16:06:18 volumio go-librespot[11679]: time="2024-04-06T16:06:18Z" level=debug msg="completed challenge" Apr 06 16:06:18 volumio volumio[775]: info: CoreCommandRouter::volumioGetQueue Apr 06 16:06:18 volumio volumio[775]: info: CoreStateMachine::getQueue Apr 06 16:06:18 volumio volumio[775]: info: CorePlayQueue::getQueue Apr 06 16:06:18 volumio go-librespot[11679]: time="2024-04-06T16:06:18Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:19 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:19 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:19 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:19 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:19 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:19 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:19 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:19 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:20 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:20 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:20 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:20 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:20 volumio volumio[775]: info: Preload queue cleared Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::ClearQueue Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::stPlaybackTimer Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::updateTrackBlock Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrackBlock Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::serviceStop Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::serviceStop Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::stop Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand stop Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::clearPlayQueue Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::saveQueue Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushQueue Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::addQueueItems Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::addQueueItems Apr 06 16:06:20 volumio volumio[775]: info: Preload queue cleared Apr 06 16:06:20 volumio volumio[775]: info: Adding Item to queue: music-library/USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata Apr 06 16:06:20 volumio volumio[775]: info: Using cached record of: music-library/USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushQueue Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::saveQueue Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::updateTrackBlock Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrackBlock Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPlay Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::play index 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::play index undefined Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::startPlaybackTimer Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::clearAddPlayTracks USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3 Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand stop Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand stop took 19 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand stop took 4 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clear Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 4 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand clear took 4 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: 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} Apr 06 16:06:20 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: No code Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: 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} Apr 06 16:06:20 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: No code Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 15ms Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 15ms Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: error: updateQueue error: null Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 23ms Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand playlistinfo took 22 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" took 22 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 10ms Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 10ms Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand play Apr 06 16:06:20 volumio volumio[775]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 31ms Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:20 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 12ms Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand play took 10 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 8ms Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 7ms Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: info: Apr 06 16:06:20 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 10 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 10 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand status took 9 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand clearerror took 17 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand clearerror took 16 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand clearerror took 16 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand playlistinfo took 13 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:20 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:20 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:20 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:20 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:20 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:20 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:20 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:20 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 49ms Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 48ms Apr 06 16:06:20 volumio volumio[775]: info: ------------------------------ 46ms Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:21 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:21 volumio volumio[775]: info: Preload queue cleared Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::ClearQueue Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::clearPlayQueue Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::saveQueue Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushQueue Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::addQueueItems Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::addQueueItems Apr 06 16:06:21 volumio volumio[775]: info: Preload queue cleared Apr 06 16:06:21 volumio volumio[775]: info: Adding Item to queue: music-library/USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata Apr 06 16:06:21 volumio volumio[775]: info: Using cached record of: music-library/USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushQueue Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::saveQueue Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::updateTrackBlock Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrackBlock Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPlay Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::play index 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::play index undefined Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::startPlaybackTimer Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::clearAddPlayTracks USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3 Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand stop Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand stop took 4 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clear Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 4 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand clear took 4 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 2 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: 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} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: No code Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: 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} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: No code Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 19ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: error: updateQueue error: null Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 19 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" took 19 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 3ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 2ms Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand play Apr 06 16:06:21 volumio volumio[775]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 26ms Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:21 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 7ms Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand play took 6 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 5ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 4ms Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 6 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 5 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 5 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: info: Apr 06 16:06:21 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 12 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand clearerror took 10 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand clearerror took 10 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand clearerror took 9 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 6 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand status took 5 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 29ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 28ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 28ms Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand clearerror took 18 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 16 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 16 milliseconds Apr 06 16:06:21 volumio volumio[775]: info: sendMpdCommand playlistinfo took 15 milliseconds Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:21 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:21 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:21 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:21 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 42ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 34ms Apr 06 16:06:21 volumio volumio[775]: info: ------------------------------ 34ms Apr 06 16:06:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2255. Apr 06 16:06:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:21 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:21 volumio go-librespot[11690]: Librespot-go daemon starting... Apr 06 16:06:21 volumio go-librespot[11690]: time="2024-04-06T16:06:21Z" level=info msg="generated new device id: fbb3a2c2210f77fd5555f78aaebfa25f9996c7a1" Apr 06 16:06:21 volumio go-librespot[11690]: time="2024-04-06T16:06:21Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:22 volumio go-librespot[11690]: time="2024-04-06T16:06:22Z" level=debug msg="obtained new client token: AABtjFevVKcpYnqpa4wLUvHKHGrUXafGZLKiXXMS3xwAoj+KQG+pnQnnXbaA8vfNZMUmbBsRpQlDNiYhCxo2Ev/ypTpF07N+PvxnlvE08CKm+EG/PBtZVxR8ouD0yhFaYgdMVzbLAAm36G7kpyTgfXinypQ2Pt7ngp6/RijYtnaJIUNARjByJ/nkLfFHFA8AJa7cqUUtyDPizEmzrBB1rPLd2ug76pLA6hcpJKjEGzPTRM81amC8BZQxSuB+" Apr 06 16:06:22 volumio go-librespot[11690]: time="2024-04-06T16:06:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:22 volumio go-librespot[11690]: time="2024-04-06T16:06:22Z" level=debug msg="completed keyexchange" Apr 06 16:06:22 volumio go-librespot[11690]: time="2024-04-06T16:06:22Z" level=debug msg="completed challenge" Apr 06 16:06:22 volumio go-librespot[11690]: time="2024-04-06T16:06:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:23 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:23 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2256. Apr 06 16:06:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:26 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:26 volumio go-librespot[11701]: Librespot-go daemon starting... Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=info msg="generated new device id: 028c730957a9338f1157cbfa68ad57109f22d275" Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=debug msg="obtained new client token: AABn7kzlvPKeyfg/ySB73saYReNa9PESFgPD4gd1wBGUt5Eq1pHBOt/kbmVGBA+nqpChovVuL5pxedDNZmPjYThQZ7S+iCwOCLiXTi6PBzzAw6qAUI6wWLBst5uNrFbSZ9R8plHFk6pS1YAbFJU1PMskoHsu/DDUSOb1dgZGJa7aXXDksY/CU1Wjc1Lm1fxMiGnzur7rZwdhlNZFalnX84orJSfiuTxqhRX5VpTaSIeLTpKr+dLg4RQexcaGawM=" Apr 06 16:06:26 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=debug msg="new websocket client" Apr 06 16:06:26 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:26 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 6 Apr 06 16:06:26 volumio go-librespot[11701]: time="2024-04-06T16:06:26Z" level=debug msg="completed keyexchange" Apr 06 16:06:27 volumio go-librespot[11701]: time="2024-04-06T16:06:27Z" level=debug msg="completed challenge" Apr 06 16:06:27 volumio go-librespot[11701]: time="2024-04-06T16:06:27Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:27 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:06:29 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:06:29 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:29 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:06:29 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 749) Apr 06 16:06:29 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 06 16:06:29 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:29 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:30 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:30 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2257. Apr 06 16:06:30 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:30 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:30 volumio go-librespot[11709]: Librespot-go daemon starting... Apr 06 16:06:30 volumio go-librespot[11709]: time="2024-04-06T16:06:30Z" level=info msg="generated new device id: b3b10e94fe34a1322b659701684d2b517fcd7a6f" Apr 06 16:06:30 volumio go-librespot[11709]: time="2024-04-06T16:06:30Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:30 volumio go-librespot[11709]: time="2024-04-06T16:06:30Z" level=debug msg="obtained new client token: AABiP5JrxyYvBMJzDBC1FeHBW+GZcq2OZ+cyWe05x1ct00RxEoEumWb//D9XjnXWrba7UAwWGs+hTLxS12RsdGHdjju3YL6qFDn8LrLvVBZ1iKTTTweQy3FmRLNPKBDaqSyv0O0Og+PHOuarZjML7346mlXe7gw8pwJIzRy2ZOFccMf2Cy+tVp90JA52j66j4vLpG9ikmjcvecyta8FziG5i2ZRlczUNwsLws40qrY7m+YCCySaFL5TVkX/iJ3w=" Apr 06 16:06:30 volumio go-librespot[11709]: time="2024-04-06T16:06:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:30 volumio go-librespot[11709]: time="2024-04-06T16:06:30Z" level=debug msg="completed keyexchange" Apr 06 16:06:31 volumio go-librespot[11709]: time="2024-04-06T16:06:31Z" level=debug msg="completed challenge" Apr 06 16:06:31 volumio go-librespot[11709]: time="2024-04-06T16:06:31Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:32 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:32 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:32 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:32 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:32 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:32 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:33 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:33 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2258. Apr 06 16:06:34 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:34 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:34 volumio go-librespot[11718]: Librespot-go daemon starting... Apr 06 16:06:34 volumio go-librespot[11718]: time="2024-04-06T16:06:34Z" level=info msg="generated new device id: b6a2fcd5336877ff02f1d60df8069f669f99cd81" Apr 06 16:06:34 volumio go-librespot[11718]: time="2024-04-06T16:06:34Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:34 volumio go-librespot[11718]: time="2024-04-06T16:06:34Z" level=debug msg="obtained new client token: AAA866L8YTbNIzllv+M+FycqPPfUG3OHkfjT9vgmLXJPFetHQ+w8kbzD7lxowCY7hVPMHY2KnYmqJG6x6JyTdKuxV1bPmesK93zIpFLIdl6IHh/YDllf0DaYGExOqVKiMO77sdh4/1L6mM8jgeL/2jxjDW1YI5lt9DM2jSdbMM64TLhXzBa1vabWEhbBchkA7yWOEyvTPJvXg1f4Vk3JiYGseMCjz626q5gmRZGFsM5+lIgHUaRB9ZnXIxiHu+A=" Apr 06 16:06:35 volumio go-librespot[11718]: time="2024-04-06T16:06:35Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:35 volumio go-librespot[11718]: time="2024-04-06T16:06:35Z" level=debug msg="completed keyexchange" Apr 06 16:06:35 volumio go-librespot[11718]: time="2024-04-06T16:06:35Z" level=debug msg="completed challenge" Apr 06 16:06:35 volumio go-librespot[11718]: time="2024-04-06T16:06:35Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:36 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:36 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2259. Apr 06 16:06:38 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:38 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:38 volumio go-librespot[11726]: Librespot-go daemon starting... Apr 06 16:06:38 volumio go-librespot[11726]: time="2024-04-06T16:06:38Z" level=info msg="generated new device id: 88f28c2fb029a874745cb40d50fef56866390609" Apr 06 16:06:38 volumio go-librespot[11726]: time="2024-04-06T16:06:38Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=debug msg="obtained new client token: AABd9gv1uQgwFRKbPo1FlHwnAd3inpaFtZYG3/DDFV7TKQR2xF+KlOOjnmSKLOwcqTWPCxDb3t+r6NG6SSnrg7c4cck3L4/SJWuMZmS+jdb/MNCWMfNRQsxQuLoM29BffzGzMzmGr8MYCPVtPDCgepqMG2JqbnrwWtLAoR7lnQhNeJylDI+c39CyhJ37HaBQAXoyO1haQevmtCPK4odey1RIYubLzcHEQQJy3VCziz5N83cj1SUERO69P5Gc" Apr 06 16:06:39 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=debug msg="new websocket client" Apr 06 16:06:39 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=debug msg="completed keyexchange" Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=debug msg="completed challenge" Apr 06 16:06:39 volumio go-librespot[11726]: time="2024-04-06T16:06:39Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:39 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:06:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:41 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:41 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:41 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:41 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:41 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:41 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:42 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:06:42 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:42 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:06:42 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 750) Apr 06 16:06:42 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 06 16:06:42 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:42 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:42 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:42 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2260. Apr 06 16:06:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:43 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:43 volumio go-librespot[11735]: Librespot-go daemon starting... Apr 06 16:06:43 volumio go-librespot[11735]: time="2024-04-06T16:06:43Z" level=info msg="generated new device id: 12d7273c19a0b2aff9465a4425bf6dbe1e6198e9" Apr 06 16:06:43 volumio go-librespot[11735]: time="2024-04-06T16:06:43Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:43 volumio go-librespot[11735]: time="2024-04-06T16:06:43Z" level=debug msg="obtained new client token: AACTP5dqQlf6trGYMVxceVIE+56FV3XVzP5nKSJh4Lli8JRTK8Qpeg7d5bnOSqI8f94cudwTtBATsa36Ic+DxceZP3MnzjT06HJ5aYYp4p0R/oRwGWQ851/HXt1WUyoF457S8IfV9RzxeTRlnbX1SZWDT6H1Z8rjhpDoK1K/tLiapSwPm+uw3mcHAy/iOdW6/s85yXlcB4RlpaOaY+oBxBxNmg5XGQ55a2Z+0HBcOaWmoPZ660isBpjK4HcRoQI=" Apr 06 16:06:43 volumio volumio[775]: info: Apr 06 16:06:43 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:43 volumio volumio[775]: info: Apr 06 16:06:43 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:43 volumio volumio[775]: info: Apr 06 16:06:43 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand clearerror took 8 milliseconds Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand clearerror took 7 milliseconds Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand clearerror took 6 milliseconds Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 06 16:06:43 volumio volumio[775]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:43 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:43 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:43 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:43 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:43 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:43 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:43 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:43 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:43 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:43 volumio volumio[775]: info: ------------------------------ 21ms Apr 06 16:06:43 volumio volumio[775]: info: ------------------------------ 20ms Apr 06 16:06:43 volumio go-librespot[11735]: time="2024-04-06T16:06:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 06 16:06:44 volumio go-librespot[11735]: time="2024-04-06T16:06:44Z" level=debug msg="completed keyexchange" Apr 06 16:06:44 volumio go-librespot[11735]: time="2024-04-06T16:06:44Z" level=debug msg="completed challenge" Apr 06 16:06:44 volumio go-librespot[11735]: time="2024-04-06T16:06:44Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:45 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:45 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2261. Apr 06 16:06:47 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:47 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:47 volumio go-librespot[11745]: Librespot-go daemon starting... Apr 06 16:06:47 volumio go-librespot[11745]: time="2024-04-06T16:06:47Z" level=info msg="generated new device id: 84d36081cb46a6345885694c1948622c9b49fe16" Apr 06 16:06:47 volumio go-librespot[11745]: time="2024-04-06T16:06:47Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:48 volumio go-librespot[11745]: time="2024-04-06T16:06:48Z" level=debug msg="obtained new client token: AACvodicgYdHoqiRdWrRUvdVJ6aDL0gV97VTbapvx9titCXlWNHX6+HMf30NIhPAU4IGXMQRSAL18rCJWhWtVit9Vj3yZKILobFn2wuTYy3azjWG224VNgUG4lRxRDMBc9TGYuII0ubrPEyyL9IICtacjwS2BfmEy31/Z8L073KXQXz3ZfoHRjb+wPNgTfHT4qVoL69Q16VIo4S66/E0rAxbDtiRiY7uDb1YYLFGxyhWMguXv0W4Ppj/qpzX" Apr 06 16:06:48 volumio go-librespot[11745]: time="2024-04-06T16:06:48Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:48 volumio go-librespot[11745]: time="2024-04-06T16:06:48Z" level=debug msg="completed keyexchange" Apr 06 16:06:48 volumio go-librespot[11745]: time="2024-04-06T16:06:48Z" level=debug msg="completed challenge" Apr 06 16:06:48 volumio go-librespot[11745]: time="2024-04-06T16:06:48Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:48 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:48 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:50 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 7 Apr 06 16:06:50 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:50 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:50 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 06 16:06:50 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 06 16:06:51 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:51 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2262. Apr 06 16:06:52 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:52 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:52 volumio go-librespot[11753]: Librespot-go daemon starting... Apr 06 16:06:52 volumio go-librespot[11753]: time="2024-04-06T16:06:52Z" level=info msg="generated new device id: 2f6c336d0bcc7c6fd61986537573391f6061074f" Apr 06 16:06:52 volumio go-librespot[11753]: time="2024-04-06T16:06:52Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:52 volumio go-librespot[11753]: time="2024-04-06T16:06:52Z" level=debug msg="obtained new client token: AAAB/6NKPTnKEyP4bFKedgOrZ3t5h6qV0eQg7Hfw9EuuEmgjCdJVns3XDhcC7CWUKJNJpagNYDNealsgHQgNJrPi9sm17RntzbAOz/8GfkynZG5H+HOVdfllv+a/SYs7hmmnD81T4mrUZEAMHqxCH5PJgSCaaHwskypWVshMFZv8qCnkMwnDS4x6Bu7NiLji5hDqP86P8zfQpTpH8B0sKEpDWjkfuP07lslRnxohJ1BtfxCZbGupcIcF6EtI+S8=" Apr 06 16:06:52 volumio sudo[11762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 06 16:06:52 volumio sudo[11762]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:52 volumio sudo[11762]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:52 volumio sudo[11765]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 06 16:06:52 volumio sudo[11765]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 06 16:06:52 volumio sudo[11765]: pam_unix(sudo:session): session closed for user root Apr 06 16:06:52 volumio go-librespot[11753]: time="2024-04-06T16:06:52Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:52 volumio volumio[775]: verbose: New Socket.io Connection to 192.168.2.180 from 192.168.2.13 UA: okhttp/4.9.2 Total Clients: 8 Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::volumioGetVisibleSources Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:52 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 06 16:06:52 volumio go-librespot[11753]: time="2024-04-06T16:06:52Z" level=debug msg="completed keyexchange" Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 06 16:06:52 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:52 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:52 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:52 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:52 volumio volumio[775]: info: Listing playlists Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 06 16:06:52 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 06 16:06:53 volumio go-librespot[11753]: time="2024-04-06T16:06:53Z" level=debug msg="completed challenge" Apr 06 16:06:53 volumio go-librespot[11753]: time="2024-04-06T16:06:53Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:54 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:54 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:54 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:54 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:54 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::volumioPlay Apr 06 16:06:54 volumio volumio[775]: info: CoreStateMachine::play index undefined Apr 06 16:06:54 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:54 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:54 volumio volumio[775]: info: CoreStateMachine::startPlaybackTimer Apr 06 16:06:54 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::clearAddPlayTracks USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3 Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand stop Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand stop took 1 milliseconds Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clear Apr 06 16:06:54 volumio volumio[775]: info: Apr 06 16:06:54 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:54 volumio volumio[775]: info: Apr 06 16:06:54 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:54 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:54 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand clear took 1 milliseconds Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" Apr 06 16:06:54 volumio volumio[775]: info: Apr 06 16:06:54 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:54 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:54 volumio volumio[775]: info: Apr 06 16:06:54 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:54 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:54 volumio volumio[775]: error: updateQueue error: null Apr 06 16:06:54 volumio volumio[775]: info: Apr 06 16:06:54 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:54 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand status took 3 milliseconds Apr 06 16:06:54 volumio volumio[775]: info: ------------------------------ 3ms Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" took 3 milliseconds Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand status took 2 milliseconds Apr 06 16:06:54 volumio volumio[775]: info: sendMpdCommand status took 2 milliseconds Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand play Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:54 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:54 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:54 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:54 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:54 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: 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} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: No code Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: 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} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: No code Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: 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} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: No code Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 33ms Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 32ms Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:55 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:55 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 34ms Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand play took 33 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 4ms Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 3ms Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:55 volumio volumio[775]: info: Apr 06 16:06:55 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand status took 15 milliseconds Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand status took 17 milliseconds Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand status took 17 milliseconds Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand status took 16 milliseconds Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand clearerror took 15 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand clearerror took 13 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand clearerror took 13 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 06 16:06:55 volumio volumio[775]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:55 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:55 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:55 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 48ms Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 47ms Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 46ms Apr 06 16:06:55 volumio volumio[775]: info: ------------------------------ 45ms Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:55 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 06 16:06:55 volumio volumio[775]: info: Received Get System Info Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:06:55 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:06:55 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:55 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:06:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:06:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2263. Apr 06 16:06:56 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:06:56 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:06:56 volumio go-librespot[11771]: Librespot-go daemon starting... Apr 06 16:06:56 volumio go-librespot[11771]: time="2024-04-06T16:06:56Z" level=info msg="generated new device id: 883a08511e9fe610352133e8d9dfdc47a4e178c2" Apr 06 16:06:56 volumio go-librespot[11771]: time="2024-04-06T16:06:56Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:06:56 volumio go-librespot[11771]: time="2024-04-06T16:06:56Z" level=debug msg="obtained new client token: AABuA1DySGPcsn5nFl4FMA28AOcLNpbdiehy99rUoi7r9kFZlt5qKF+VOrUP01brWfxFtOexqKmG3g1eEqnTo9gxjFqurac9iHQCVLVu3H+j1fqp0yP4O6tcQ5vZyXfwrAyek0tAujzTPe++eBUwQDyU7gJvdxNgQpBVDUF8UvfoD/8tYe6yFxpAj5jbY9f+9Mo6i7A/XAHc8z363XnLx2aVW0uQAPE5cLAaQ7S4wT9aqZ25yyN9oi5y1NQVtnI=" Apr 06 16:06:56 volumio go-librespot[11771]: time="2024-04-06T16:06:56Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:06:56 volumio go-librespot[11771]: time="2024-04-06T16:06:56Z" level=debug msg="completed keyexchange" Apr 06 16:06:57 volumio go-librespot[11771]: time="2024-04-06T16:06:57Z" level=debug msg="completed challenge" Apr 06 16:06:57 volumio go-librespot[11771]: time="2024-04-06T16:06:57Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:06:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:06:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPlay Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::play index undefined Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::startPlaybackTimer Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::clearAddPlayTracks USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3 Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand stop Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand stop took 2 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clear Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 4 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand clear took 4 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 2 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 2 milliseconds Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: 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} Apr 06 16:06:57 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: No code Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: 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} Apr 06 16:06:57 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState stateService stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: No code Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 25ms Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 25ms Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: error: updateQueue error: null Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 28ms Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand playlistinfo took 27 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand add "USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3" took 26 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 4ms Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 4ms Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand play Apr 06 16:06:57 volumio volumio[775]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 34ms Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces system playlist update Apr 06 16:06:57 volumio volumio[775]: info: Ignoring MPD Status Update Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 19ms Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand play took 17 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 15ms Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 14ms Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: info: Apr 06 16:06:57 volumio volumio[775]: ---------------------------- MPD announces state update: player Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::getState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand status Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 7 milliseconds Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 7 milliseconds Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand status took 8 milliseconds Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseState Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand clearerror took 8 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand clearerror took 7 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand clearerror took 6 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 06 16:06:57 volumio volumio[775]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:57 volumio volumio[775]: verbose: ControllerMpd::parseTrackInfo Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:57 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:57 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: ControllerMpd::pushState Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::servicePushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":323,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Sposa son disprezzata (feat. Aciel Martinez Pol)","artist":"䄀挀椀攀氀 䴀愀爀琀椀渀攀稀 倀漀氀","album":"Sposa son disprezzata (feat. Aciel Martinez Pol)","uri":"USB/Elements/PLAYLISTS 2024/Sposa Son Disprezzata/Sposa Son Disprezzata/01 - Sposa son disprezzata (feat. Aciel Martinez Pol).mp3","trackType":"mp3"} Apr 06 16:06:57 volumio volumio[775]: verbose: CURRENT POSITION 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState stateService pause Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::syncState currentStatus stop Apr 06 16:06:57 volumio volumio[775]: info: CoreStateMachine::pushState Apr 06 16:06:57 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:06:57 volumio volumio[775]: info: CoreCommandRouter::volumioPushState Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 34ms Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 32ms Apr 06 16:06:57 volumio volumio[775]: info: ------------------------------ 32ms Apr 06 16:06:57 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:06:57 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:06:59 volumio volumio[775]: info: CoreCommandRouter::volumioGetQueue Apr 06 16:06:59 volumio volumio[775]: info: CoreStateMachine::getQueue Apr 06 16:06:59 volumio volumio[775]: info: CorePlayQueue::getQueue Apr 06 16:07:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2264. Apr 06 16:07:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:00 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:00 volumio go-librespot[11822]: Librespot-go daemon starting... Apr 06 16:07:00 volumio go-librespot[11822]: time="2024-04-06T16:07:00Z" level=info msg="generated new device id: 81864965744e5876bca407123eb9d22cf8bef63c" Apr 06 16:07:00 volumio go-librespot[11822]: time="2024-04-06T16:07:00Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:00 volumio go-librespot[11822]: time="2024-04-06T16:07:00Z" level=debug msg="obtained new client token: AADPwtBXFakb6uaObjQ2Jpae8ZvxKcmVF6NmUGUOkxFER+TAhXMSek69/+aXls1Ew1jJYeiYmi7eph7KJ4+camFHeTPZ+tuPzndwdLatL1E6mA8c5iVjCMfli+KEbPospMfIr5O9P+01U9X/rVCB9ROP6M7MAr0l5WQKZWbkpqP6n9nourSqk4iNaMvl8xZeOyfknXOT5yfUxwQnuzYrijAjWArp0xzhn5w/Tcob2VY6vdTHrFS8/Pb2dw31APc=" Apr 06 16:07:00 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:00 volumio go-librespot[11822]: time="2024-04-06T16:07:00Z" level=debug msg="new websocket client" Apr 06 16:07:00 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:07:01 volumio go-librespot[11822]: time="2024-04-06T16:07:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:01 volumio go-librespot[11822]: time="2024-04-06T16:07:01Z" level=debug msg="completed keyexchange" Apr 06 16:07:01 volumio go-librespot[11822]: time="2024-04-06T16:07:01Z" level=debug msg="completed challenge" Apr 06 16:07:01 volumio go-librespot[11822]: time="2024-04-06T16:07:01Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:01 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:07:03 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:07:03 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:03 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:07:03 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 751) Apr 06 16:07:04 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 06 16:07:04 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:04 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:07:04 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:07:04 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:07:04 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:04 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:04 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:07:04 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:04 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2265. Apr 06 16:07:04 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:04 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:04 volumio go-librespot[11831]: Librespot-go daemon starting... Apr 06 16:07:04 volumio go-librespot[11831]: time="2024-04-06T16:07:04Z" level=info msg="generated new device id: 30f0e99d4d7b6729c5f7ffc553036092e33376f3" Apr 06 16:07:04 volumio go-librespot[11831]: time="2024-04-06T16:07:04Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:05 volumio go-librespot[11831]: time="2024-04-06T16:07:05Z" level=debug msg="obtained new client token: AACigCA7PfU7wOMmHRYMWd02QjhDaC8mF6yKNNSsPuZ+gMjmY98oT1y8mMpcwc9Lmc7Oys5IvE2PpTtzE/u632PPF2pBfV1M01+RcYGLF9fWym9rW2W2K41QQ9oOHMy40xcAzY1GU5+eQvAW1Onz6BAqAXnhZijd2BtkHTIYO51qVvnHkndES+NME8PfxKOrLrUFTPSCQfu0Fo2AqeSdUGR4LHu8l4VBPGbiwo8iFdf+qHSI/ZRTpYYKrstT" Apr 06 16:07:05 volumio go-librespot[11831]: time="2024-04-06T16:07:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:05 volumio go-librespot[11831]: time="2024-04-06T16:07:05Z" level=debug msg="completed keyexchange" Apr 06 16:07:05 volumio go-librespot[11831]: time="2024-04-06T16:07:05Z" level=debug msg="completed challenge" Apr 06 16:07:06 volumio go-librespot[11831]: time="2024-04-06T16:07:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: info: Retrieving Cloud Streaming UI Apr 06 16:07:07 volumio volumio[775]: info: Getting Tidal Cloud Configuration Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: info: Getting Qobuz Cloud Configuration Apr 06 16:07:07 volumio volumio[775]: info: Asking plugin for UI Config Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: info: Getting Spotify Cloud Configuration Apr 06 16:07:07 volumio volumio[775]: info: Asking plugin for UI Config Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: info: Saving Spotify Acccount Apr 06 16:07:07 volumio volumio[775]: info: Got Tidal Cloud Configuration Apr 06 16:07:07 volumio volumio[775]: info: Got it Apr 06 16:07:07 volumio volumio[775]: info: Got it Apr 06 16:07:07 volumio volumio[775]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:07 volumio volumio[775]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 06 16:07:07 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 06 16:07:07 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:07 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2266. Apr 06 16:07:09 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:09 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:09 volumio go-librespot[11839]: Librespot-go daemon starting... Apr 06 16:07:09 volumio go-librespot[11839]: time="2024-04-06T16:07:09Z" level=info msg="generated new device id: edb1e9958534ab0866197b493086c9e325f0933a" Apr 06 16:07:09 volumio go-librespot[11839]: time="2024-04-06T16:07:09Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:09 volumio go-librespot[11839]: time="2024-04-06T16:07:09Z" level=debug msg="obtained new client token: AAAW6Glp0JIXbrnSrWPhuDVCh1aGGSMaHWvk0vH5i+GvpuMkYvvkMMGcGuvHcF1QAlgLUoUmV5wtPCjTbl+r+Cys65lE2zktkW23iUf5jo9C77L2yj0lWm4ZC3vEDMKZLx5rHUAZCfut3dtm/z0RRtXsKoG2ckOTK1aIs6g/MEZAvYAi/FvnCuItoIXjoXAq4zgpKVL+6w8oaY+6V363JxsXFrP6yTzUqCuDsZ4pUjPvQtjRibsvq7nHNdKv7Uw=" Apr 06 16:07:09 volumio go-librespot[11839]: time="2024-04-06T16:07:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:09 volumio go-librespot[11839]: time="2024-04-06T16:07:09Z" level=debug msg="completed keyexchange" Apr 06 16:07:10 volumio go-librespot[11839]: time="2024-04-06T16:07:10Z" level=debug msg="completed challenge" Apr 06 16:07:10 volumio go-librespot[11839]: time="2024-04-06T16:07:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 06 16:07:10 volumio volumio[775]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 06 16:07:10 volumio volumio[775]: info: Received Get System Version Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 06 16:07:10 volumio volumio[775]: info: Received Get System Info Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:07:10 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:10 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:10 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:07:10 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:10 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:11 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 06 16:07:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2267. Apr 06 16:07:13 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:13 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:13 volumio go-librespot[11848]: Librespot-go daemon starting... Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=info msg="generated new device id: 3fea67cf0b9f2380ac25a81cb95f7f1f2c83614a" Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=debug msg="obtained new client token: AAC0wu3dy0U3fMSE2m5iVv7QxDt7HevrQzfaQMuANr4mkGVoeEsWeGrJ2/CifMuz0chamQ9wR0mteg1bVXvyyEK0iWAFF1RzphHZiKnn9/0xMku7qTN035+tRnyJUn0wdR0eQTOjT1pRqcmcjHsDaGfdUpF5S40g7aYuRiJsypzzNIIISOLV8RNVbp9MG4tBiOy5Xa+1r75rC5mxDFcBT9rCNL5WpkDYmnvyKJPBgfWSQESW5nprsXqXmBTky8I=" Apr 06 16:07:13 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 06 16:07:13 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 06 16:07:13 volumio volumio[775]: info: Discovery: Getting this device information Apr 06 16:07:13 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:13 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:13 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 06 16:07:13 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=debug msg="new websocket client" Apr 06 16:07:13 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:07:13 volumio go-librespot[11848]: time="2024-04-06T16:07:13Z" level=debug msg="completed keyexchange" Apr 06 16:07:14 volumio go-librespot[11848]: time="2024-04-06T16:07:14Z" level=debug msg="completed challenge" Apr 06 16:07:14 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:14 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 06 16:07:14 volumio go-librespot[11848]: time="2024-04-06T16:07:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:14 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:07:14 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 06 16:07:14 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 06 16:07:14 volumio volumio[775]: info: Received Get System Version Apr 06 16:07:14 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 06 16:07:16 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:07:16 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:16 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:07:16 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 752) Apr 06 16:07:16 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 06 16:07:16 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:16 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:17 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:17 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2268. Apr 06 16:07:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:17 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:17 volumio go-librespot[11870]: Librespot-go daemon starting... Apr 06 16:07:17 volumio go-librespot[11870]: time="2024-04-06T16:07:17Z" level=info msg="generated new device id: b0d00d41a70a14928ce84134ee210dbd4af8b510" Apr 06 16:07:17 volumio go-librespot[11870]: time="2024-04-06T16:07:17Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:17 volumio go-librespot[11870]: time="2024-04-06T16:07:17Z" level=debug msg="obtained new client token: AADREdYvNjEAX/wRrQ+sTTJ/k2qIoRxPNckPHzg4nAVw4xQtovpimmtX4mbYvvehhqXO5FSs9DlBZblVJZiPieWsfkvv92eEkdRFohXVinLhU1K0BKhlYzTARin2tY6gkoBhe9OQ6chpfwR/a08NGhcksU4YNPqfrgZgNYmP+oEeK11PP/JdQ3fdCH7LjoEB7zgsnU+TfaBcqTfWHnCDHzEMOlMDv/9JdqBsqGWWLc00I7oE4wzWsdog5xXgX+M=" Apr 06 16:07:18 volumio go-librespot[11870]: time="2024-04-06T16:07:18Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:18 volumio go-librespot[11870]: time="2024-04-06T16:07:18Z" level=debug msg="completed keyexchange" Apr 06 16:07:18 volumio go-librespot[11870]: time="2024-04-06T16:07:18Z" level=debug msg="completed challenge" Apr 06 16:07:18 volumio go-librespot[11870]: time="2024-04-06T16:07:18Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:20 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:20 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:21 volumio volumio-remote-updater[564]: No test mode Apr 06 16:07:21 volumio volumio-remote-updater[564]: No alpha test mode Apr 06 16:07:21 volumio volumio[775]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Apr 06 16:07:21 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Apr 06 16:07:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2269. Apr 06 16:07:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:21 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:21 volumio go-librespot[11880]: Librespot-go daemon starting... Apr 06 16:07:21 volumio go-librespot[11880]: time="2024-04-06T16:07:21Z" level=info msg="generated new device id: e6afafcfdb1c3b61fb35eb250d0504e477dda5d3" Apr 06 16:07:21 volumio go-librespot[11880]: time="2024-04-06T16:07:21Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:22 volumio go-librespot[11880]: time="2024-04-06T16:07:22Z" level=debug msg="obtained new client token: AACMw/mrRyVM4s2aradlBbJSeXLr0vA0qvcqNW+s4caNQFNifsuwgelAAW/HN3Rp5W8NVRYp49vyhkdFX4mlacMROIQFfDznWPZhF85sW7b44yDUlIAQ6/TKWOGp0oTQPKX6Q9FHe7NVKwrya9l1o/gRNIyLuAWSk9cv/PmohMf8PXmhP2SJ1sY3kgb5XhjmEmcBifusnrzjO+wVHdQSRRF3BTTDS+7RTu2Qfcx9QaEQhdoA4W1qwoC7NS/W" Apr 06 16:07:22 volumio go-librespot[11880]: time="2024-04-06T16:07:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:22 volumio go-librespot[11880]: time="2024-04-06T16:07:22Z" level=debug msg="completed keyexchange" Apr 06 16:07:22 volumio volumio[775]: info: CoreCommandRouter::Close All Modals sent Apr 06 16:07:22 volumio go-librespot[11880]: time="2024-04-06T16:07:22Z" level=debug msg="completed challenge" Apr 06 16:07:22 volumio go-librespot[11880]: time="2024-04-06T16:07:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:23 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:23 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2270. Apr 06 16:07:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:26 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:26 volumio go-librespot[11888]: Librespot-go daemon starting... Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=info msg="generated new device id: 0efac394cb2959734204bc704329ae152621f926" Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=debug msg="obtained new client token: AACCsBRg5bE1BzAmRk7L5FkzMBZfksp/3djfiCjsUaKT3TmCkGbSJjcfzFQwNNadmkaiP1NCS+4yNAl1GhQVZ8LQmAQqF81GGF7X3sUMIwxHQIiMNgrP94wpcgolBZcJo1BiAygpTbl/IgT2lO0ZsrNw58fVjoyM1keOGF5FCPKFckB5uHzCn68h5fn+Jzpl1U4oLMeIM7kiDs1jcVdEYkkzI0VDq3AL5F0XRnGOYkyEEJt2jYpqWQlnjoalGg0=" Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 06 16:07:26 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:26 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=debug msg="new websocket client" Apr 06 16:07:26 volumio go-librespot[11888]: time="2024-04-06T16:07:26Z" level=debug msg="completed keyexchange" Apr 06 16:07:27 volumio go-librespot[11888]: time="2024-04-06T16:07:27Z" level=debug msg="completed challenge" Apr 06 16:07:27 volumio go-librespot[11888]: time="2024-04-06T16:07:27Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:27 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:29 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:07:29 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:29 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:07:29 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 753) Apr 06 16:07:29 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 06 16:07:29 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:29 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:30 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:30 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2271. Apr 06 16:07:30 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:30 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:30 volumio go-librespot[11896]: Librespot-go daemon starting... Apr 06 16:07:30 volumio go-librespot[11896]: time="2024-04-06T16:07:30Z" level=info msg="generated new device id: e0c5aaa998b517a46faeff520ccf9ea0b9768a0e" Apr 06 16:07:30 volumio go-librespot[11896]: time="2024-04-06T16:07:30Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:30 volumio go-librespot[11896]: time="2024-04-06T16:07:30Z" level=debug msg="obtained new client token: AADms7syryPtMyIfboE6UwCzGc8/VSX8qI+zGqFYbxm3JSoAiUH9PEZ5WIC0Dtm/B7zhG6Ej1vM/3DKYYuXTMy+I8X94eUZgHME9LjR9b5YWkZFDsMX2+RyRVcdDgQAJmhzxZ4hbmxAapGcxkLz9GM15o5xExjfuoal7AE30E0B/uytMgxrP+IaVx/nWnjzfXLrwaPrubQadFWefqg/Dr4TxDSlIEVYI2LVJ1JVIIgKTlWff4uedwEn/NgZuqI0=" Apr 06 16:07:30 volumio go-librespot[11896]: time="2024-04-06T16:07:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:30 volumio go-librespot[11896]: time="2024-04-06T16:07:30Z" level=debug msg="completed keyexchange" Apr 06 16:07:31 volumio go-librespot[11896]: time="2024-04-06T16:07:31Z" level=debug msg="completed challenge" Apr 06 16:07:31 volumio go-librespot[11896]: time="2024-04-06T16:07:31Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:33 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:33 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2272. Apr 06 16:07:34 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:34 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:34 volumio go-librespot[11905]: Librespot-go daemon starting... Apr 06 16:07:34 volumio go-librespot[11905]: time="2024-04-06T16:07:34Z" level=info msg="generated new device id: d7519512e7f95e7b796db91dc47c0bd334b9950b" Apr 06 16:07:34 volumio go-librespot[11905]: time="2024-04-06T16:07:34Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:34 volumio go-librespot[11905]: time="2024-04-06T16:07:34Z" level=debug msg="obtained new client token: AABIdQ6whQ9QZNXUxsCHqG7E7Oz3DyoMzkJPxj4TidJxICNOQLYLAXhqZT84y0KjBJBZ+1sNgfDGdGlRFPd62EBNd+vA3aNQqRVgGMalS7bXF2Wo0CKvDIDRg3AsxO+poWMYLz4Axa78DycwmJzBJKLSXBdwCnfBTC8vIdBYuY3f4PVMD0E1wnlMfETPqZ+2XeK2ur+J6IlKJPYglz/mGBv5Myls7CKBkFYb6VhIbXPdbczd3d7YuBlnCx7Sdmw=" Apr 06 16:07:35 volumio go-librespot[11905]: time="2024-04-06T16:07:35Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: info: Retrieving Cloud Streaming UI Apr 06 16:07:35 volumio volumio[775]: info: Getting Tidal Cloud Configuration Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: info: Getting Qobuz Cloud Configuration Apr 06 16:07:35 volumio volumio[775]: info: Asking plugin for UI Config Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: info: Getting Spotify Cloud Configuration Apr 06 16:07:35 volumio volumio[775]: info: Asking plugin for UI Config Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: info: Saving Spotify Acccount Apr 06 16:07:35 volumio volumio[775]: info: Got Tidal Cloud Configuration Apr 06 16:07:35 volumio volumio[775]: info: Got it Apr 06 16:07:35 volumio volumio[775]: info: Got it Apr 06 16:07:35 volumio volumio[775]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 06 16:07:35 volumio volumio[775]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::volumioGetBrowseSources Apr 06 16:07:35 volumio go-librespot[11905]: time="2024-04-06T16:07:35Z" level=debug msg="completed keyexchange" Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 06 16:07:35 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 06 16:07:35 volumio go-librespot[11905]: time="2024-04-06T16:07:35Z" level=debug msg="completed challenge" Apr 06 16:07:35 volumio go-librespot[11905]: time="2024-04-06T16:07:35Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:36 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:36 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2273. Apr 06 16:07:38 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:38 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:38 volumio go-librespot[11913]: Librespot-go daemon starting... Apr 06 16:07:38 volumio go-librespot[11913]: time="2024-04-06T16:07:38Z" level=info msg="generated new device id: 5e724a521882e572309282fd87100630cb675645" Apr 06 16:07:38 volumio go-librespot[11913]: time="2024-04-06T16:07:38Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=debug msg="obtained new client token: AABORT/xo38Dil8cUa094PQlaq8N2QzWUywCaMODRbsHMXlayEO9V1+2UWvKV6wtipYlCtWlYJcZq39ikJ7llA5+3WLmEpqgmOW+CJM6IB8DA5ZT9v4BsgfF9e0lgaST8RNPGUEYRPYIqzzImtfhqZO0GgjJYXYnJ5Rd/nzVSjb94lMvBkTg5IWG0KE4H3nbvrayPfpm1TaAjt4M6rEnV33CiP2rrWZWsSEpHNbuM2nY3cfc9X8B7TkmPQMA" Apr 06 16:07:39 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=debug msg="new websocket client" Apr 06 16:07:39 volumio volumio[775]: info: Connection to go-librespot Websocket established Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:39 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=debug msg="completed keyexchange" Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=debug msg="completed challenge" Apr 06 16:07:39 volumio go-librespot[11913]: time="2024-04-06T16:07:39Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:39 volumio volumio[775]: info: Connection to go-librespot Websocket closed Apr 06 16:07:42 volumio volumio[775]: info: Getting Spotify volume Apr 06 16:07:42 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:42 volumio volumio[775]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 06 16:07:42 volumio volumio[775]: (node:775) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 754) Apr 06 16:07:42 volumio volumio[775]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 06 16:07:42 volumio volumio[775]: info: CoreCommandRouter::volumioGetState Apr 06 16:07:42 volumio volumio[775]: info: CorePlayQueue::getTrack 0 Apr 06 16:07:42 volumio volumio[775]: info: Initializing connection to go-librespot Websocket Apr 06 16:07:42 volumio volumio[775]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 06 16:07:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 06 16:07:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2274. Apr 06 16:07:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 06 16:07:43 volumio systemd[1]: Started go-librespot Daemon. Apr 06 16:07:43 volumio go-librespot[11922]: Librespot-go daemon starting... Apr 06 16:07:43 volumio go-librespot[11922]: time="2024-04-06T16:07:43Z" level=info msg="generated new device id: 54486e99462b00e4d81b1acdb26c697853d603f9" Apr 06 16:07:43 volumio go-librespot[11922]: time="2024-04-06T16:07:43Z" level=debug msg="stored credentials found for radiopokopokito" Apr 06 16:07:43 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 06 16:07:43 volumio go-librespot[11922]: time="2024-04-06T16:07:43Z" level=debug msg="obtained new client token: AADkTigtIVrH4Pxdn66V4tcrKw7J7YRJHgGZgVblV4WsJtZPpotPtMAgwBxakX5QhGOjYZ3/zRdltY7pPwxj6ZL6gUJW/lqq2T+ceJjJswlk6e1DkgpCORQX9sIYT0A/cd1+8mh9EaCs0JAA8wpiRjG+yz7Kyqz2JYI5JM8E4YVO1MeSrQWtH3zbym6TZ78XjU47ogTub+sh5uiQch9Yldw9H6AKlYr6SvBmx8CBo2PvqkuQK+YjzeZ7Au1HbJ0=" Apr 06 16:07:43 volumio go-librespot[11922]: time="2024-04-06T16:07:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 06 16:07:43 volumio go-librespot[11922]: time="2024-04-06T16:07:43Z" level=debug msg="completed keyexchange" Apr 06 16:07:44 volumio go-librespot[11922]: time="2024-04-06T16:07:44Z" level=debug msg="completed challenge" Apr 06 16:07:44 volumio go-librespot[11922]: time="2024-04-06T16:07:44Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 06 16:07:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 06 16:07:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 06 16:07:44 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Apr 06 16:07:44 volumio volumio[775]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Apr 06 16:07:45 volumio volumio[775]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 06 16:07:45 volumio volumio[775]: Error: getaddrinfo -3007 Apr 06 16:07:45 volumio volumio[775]: at errnoException (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:199:11) Apr 06 16:07:45 volumio volumio[775]: at getaddrinfo_complete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:112:10) Apr 06 16:07:45 volumio volumio[775]: at GetAddrInfoReqWrap.oncomplete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:120:9) { Apr 06 16:07:45 volumio volumio[775]: code: -3007, Apr 06 16:07:45 volumio volumio[775]: errno: -3007, Apr 06 16:07:45 volumio volumio[775]: syscall: 'getaddrinfo' Apr 06 16:07:45 volumio volumio[775]: } Apr 06 16:07:45 volumio volumio[775]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 06 16:07:45 volumio sudo[11941]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-06 16:06 Apr 06 16:07:45 volumio sudo[11941]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"