-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2026-03-28 19:32:05 CET. -- Mar 28 19:31:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 359. Mar 28 19:31:01 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:01 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:02 volumio go-librespot[9295]: go-librespot daemon starting... Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=debug msg="app state loaded" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=debug msg="new websocket client" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:02 volumio go-librespot[9295]: time="2026-03-28T19:31:02+01:00" level=info msg="zeroconf server listening on port 35549" Mar 28 19:31:03 volumio go-librespot[9295]: time="2026-03-28T19:31:03+01:00" level=debug msg="obtained new client token: AADMT2PEavHNaBYU4FchEw1PHCvYpGLTBq522nKbIkBlAtexx2LUcizZhIW/tbGe6CVs3uQqfZCu0/GWPiAc2Bq7S/K5mHflCxYY3nJpwJIN8w4kS8ZzfBbG0eZrM9FmDXqDbDGWDTdTWkYRGZAOmiDUqKrZWIT2N1IS4mcEDJioIhM4LAsjv2dhIfxnKMTgbn08S75nECBTPcRhQF6Dolx+Sid/ybOs/nHq49gQtCbVql3xO+Ga2es=" Mar 28 19:31:03 volumio go-librespot[9295]: time="2026-03-28T19:31:03+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:03 volumio go-librespot[9295]: time="2026-03-28T19:31:03+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:03 volumio go-librespot[9295]: time="2026-03-28T19:31:03+01:00" level=debug msg="completed challenge" Mar 28 19:31:03 volumio go-librespot[9295]: time="2026-03-28T19:31:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 360. Mar 28 19:31:06 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:06 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:06 volumio go-librespot[9306]: go-librespot daemon starting... Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="app state loaded" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=info msg="zeroconf server listening on port 40485" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="obtained new client token: AACRj46DAbNpdOAuLSCvCIgLIV3E2aDGbJPtmGa9RYgmCAUXL30D5Ddn0rLmzAeO8yDKLwVpHncx466FwxZjfn0k38h8c8Uymz01ezwETDM7If8zMTCmZppl1grdw0HSG3dpqLCkw0x3ULrVJCSUdjZfjOa2GGb4/ubnItvonYAc03wRRSDC4mD26NSbp3NR/Q8EJ9V9jk7AQpRex4TmsC+U9CczWpbjj+BUkGAtTjvZSke+5UQCPu8Epw==" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:06 volumio go-librespot[9306]: time="2026-03-28T19:31:06+01:00" level=debug msg="completed challenge" Mar 28 19:31:07 volumio go-librespot[9306]: time="2026-03-28T19:31:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:09 volumio systemd-journald[300]: Suppressed 8302 messages from volumio.service Mar 28 19:31:09 volumio volumio[1032]: info: ------------------------------ 69ms Mar 28 19:31:09 volumio volumio[1032]: info: ------------------------------ 69ms Mar 28 19:31:09 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 57 milliseconds Mar 28 19:31:09 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 56 milliseconds Mar 28 19:31:09 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 56 milliseconds Mar 28 19:31:09 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:09 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:09 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:09 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:09 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:09 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:09 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":261,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"David Byrne - Feelings - 11 - Burnt By The Sun.mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/David Byrne - 1997 - Feelings/David Byrne - Feelings - 11 - Burnt By The Sun.mp3","trackType":"mp3"} Mar 28 19:31:09 volumio volumio[1032]: verbose: CURRENT POSITION 2291 Mar 28 19:31:09 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:09 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:09 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:09 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:09 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:09 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":261,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"David Byrne - Feelings - 11 - Burnt By The Sun.mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/David Byrne - 1997 - Feelings/David Byrne - Feelings - 11 - Burnt By The Sun.mp3","trackType":"mp3"} Mar 28 19:31:10 volumio volumio[1032]: verbose: CURRENT POSITION 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:10 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":261,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"David Byrne - Feelings - 11 - Burnt By The Sun.mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/David Byrne - 1997 - Feelings/David Byrne - Feelings - 11 - Burnt By The Sun.mp3","trackType":"mp3"} Mar 28 19:31:10 volumio volumio[1032]: verbose: CURRENT POSITION 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:10 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:10 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:10 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:10 volumio volumio[1032]: info: ------------------------------ 137ms Mar 28 19:31:10 volumio volumio[1032]: info: ------------------------------ 130ms Mar 28 19:31:10 volumio volumio[1032]: info: ------------------------------ 130ms Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 361. Mar 28 19:31:10 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:10 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:10 volumio go-librespot[9317]: go-librespot daemon starting... Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="app state loaded" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=info msg="zeroconf server listening on port 42617" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="obtained new client token: AABbiXJfifLAgcmpinG/FP7gMkBrJKW808CPyjaMrlpsYZAnOiouGdGFtHoR8Hb6i9DM2drNoypgh+VlOSEERHspUsa1GMV6OI1Yo/obQAtGO0JPyeEU4SVhqc52fiSgDcPm/OKTEKeMRGAmiVtGtvIVQLzbFfzWYZ4gBmjz3GFcNPIZzKsnDjNn8CL22/9FLtAKQg7uvKpJHOT+Y9PcbjVtDTTpyXhP8aap5oHMv3iykBt5nOTWT8h7mA==" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=debug msg="completed challenge" Mar 28 19:31:10 volumio go-librespot[9317]: time="2026-03-28T19:31:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:12 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:12 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 362. Mar 28 19:31:14 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:14 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:14 volumio go-librespot[9350]: go-librespot daemon starting... Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="app state loaded" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=info msg="zeroconf server listening on port 36763" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="obtained new client token: AAD57G4/+/EYgmDf4IHjznPcmADSLD+ORy2EXmvlz1dkMfAp+4fVH1iQ+WNLXRZKvblQsLiNU7hUsUaR29ZApYuZrltEVLdgmC5qYJsEMXImHGwdavl/KD9r+awr+1Loa1rXm1IpnQOVj04WOa+PkBLAK3FPkhd8ONVDbIyPN1Ry4hbVo6GLxYTADPZgxBlLxJfMnd31h/G/pGNqwqTPqtsektlsq4W+LiQ/TCCJQ6wGnN5zZiWsj+lLZg==" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=debug msg="completed challenge" Mar 28 19:31:14 volumio go-librespot[9350]: time="2026-03-28T19:31:14+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:15 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:15 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 363. Mar 28 19:31:17 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:17 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:17 volumio go-librespot[9364]: go-librespot daemon starting... Mar 28 19:31:17 volumio go-librespot[9364]: time="2026-03-28T19:31:17+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:17 volumio go-librespot[9364]: time="2026-03-28T19:31:17+01:00" level=debug msg="app state loaded" Mar 28 19:31:17 volumio go-librespot[9364]: time="2026-03-28T19:31:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:18 volumio volumio[1032]: info: Adding mnt/NAS/ELEMENTS/David Byrne - 1997 - Feelings/David Byrne - Feelings - 11 - Burnt By The Sun.mp3 to favourites using generic method Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=info msg="zeroconf server listening on port 44725" Mar 28 19:31:18 volumio volumio[1032]: info: Saving local item favourites Mar 28 19:31:18 volumio volumio[1032]: info: Pushing Favourites {"uri":"mnt/NAS/ELEMENTS/David Byrne - 1997 - Feelings/David Byrne - Feelings - 11 - Burnt By The Sun.mp3","favourite":true} Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="obtained new client token: AADFpcBoAiQDkSCnQxRbj94nNN9pqFxJTsBnwK0bIVmCLt47kB5HaQBeAbapGfR78wd6J4HPPKtW0USDInqqth3FoXVEhWva+23vm0cX5mJT5cg6h4IYoCvYpGcv1W9+LpBXS21vsmwPclQCeCQqdus7UhZ6gIqjSqwkNo4s8a7tiEPfCj+XEX33xnJFyyeTLrQCadF4DAty8EJuDjO5hqPGwqMpETFiL8TdASbGGiAqgARgBJTGExQ=" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=debug msg="completed challenge" Mar 28 19:31:18 volumio go-librespot[9364]: time="2026-03-28T19:31:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:18 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:18 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:21 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:21 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 364. Mar 28 19:31:21 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:21 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:21 volumio go-librespot[9397]: go-librespot daemon starting... Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="app state loaded" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=info msg="zeroconf server listening on port 40995" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="obtained new client token: AAAhwCiU+bO7IlZ1/VpuREHdDOVmFzKPl6x4NSiNe47lAsaZa/gB6NPCsVqYPtKyIxNGLwj4XdELN8EKmQ593SXrCuK+LrZm8KWRkQ14mDqFYjCbVeY5Wy4Ah6uPwUtTUIX0Jvz0wOgprxeHqqMbpnDVChXrU7RBKcd8duMhKGS3r015Elq8S5v3ukLzk+iOrSu2ncT5qULPhs9ujgEgVW81KotsGzH2w8OnQYkO10zIPj6kLR243qWAKA==" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:21 volumio go-librespot[9397]: time="2026-03-28T19:31:21+01:00" level=debug msg="completed challenge" Mar 28 19:31:22 volumio go-librespot[9397]: time="2026-03-28T19:31:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:24 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:24 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:25 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 365. Mar 28 19:31:25 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:25 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:25 volumio go-librespot[9413]: go-librespot daemon starting... Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="app state loaded" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=info msg="zeroconf server listening on port 46047" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="obtained new client token: AABUmp+BKrF6i8tySZs3ybNITeApKPWfeZ9xJlyhgpD00QzIK+clxQ6Gz++Lpyqo2Lp4cy2AFGdThoqduZTPgIOib9wNUuWTfhIzzLDf1RR08d9ZoiYtz9c1gJIsOFkktqDWRGfudw30jbOqL93FT98IlHMb6cADStXVa3upWZO23MDoVIfyJyepdNkwSK5e7Z/3xAfoD+m0Ryu5zv7UQq1EH/uZLrQgDVdb8kOQej/BG/DwCG3WKNqhJQ==" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 2291 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=debug msg="completed challenge" Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand stop took 18 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand stop took 14 milliseconds Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand status took 8 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand clear took 8 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac" Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: 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} Mar 28 19:31:25 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio go-librespot[9413]: time="2026-03-28T19:31:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:25 volumio volumio[1032]: info: No code Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:25 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: 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} Mar 28 19:31:25 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio volumio[1032]: info: No code Mar 28 19:31:25 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:25 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:25 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 79ms Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 79ms Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 83ms Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 80 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac" took 79 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 6ms Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 6ms Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:25 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:31:25 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 95ms Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: info: Mar 28 19:31:25 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:25 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 22ms Mar 28 19:31:25 volumio volumio[1032]: info: sendMpdCommand play took 19 milliseconds Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 17ms Mar 28 19:31:25 volumio volumio[1032]: info: ------------------------------ 15ms Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand status took 7 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand status took 5 milliseconds Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: Mar 28 19:31:26 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand status took 21 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 18 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 18 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 17 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand status took 16 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand status took 14 milliseconds Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:26 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:26 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 61ms Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 94ms Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 93ms Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 72 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 71 milliseconds Mar 28 19:31:26 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 71 milliseconds Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:26 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:26 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":609,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Black Lake","artist":"Björk","album":"Vulnicura","uri":"NAS/ELEMENTS/Björk - Vulnicura (2015) [24bit FLAC]/04 - Black Lake.flac","trackType":"flac"} Mar 28 19:31:26 volumio volumio[1032]: verbose: CURRENT POSITION 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:26 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:26 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:26 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 180ms Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 174ms Mar 28 19:31:26 volumio volumio[1032]: info: ------------------------------ 172ms Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:26 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:27 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:27 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1021 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand stop took 19 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3 Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand stop took 9 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 5 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 2 milliseconds Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand clear took 6 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 5 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 5 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 4ms Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3" Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:31:28 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 24ms Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 23ms Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 23ms Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 21 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3" took 20 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 12ms Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 11ms Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:31:28 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 36ms Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:28 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 12ms Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand play took 6 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 4ms Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 17 milliseconds Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 18 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 18 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 27ms Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: Mar 28 19:31:28 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 10 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 4 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand status took 3 milliseconds Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:28 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:28 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 86ms Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 85ms Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 58 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 57 milliseconds Mar 28 19:31:28 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 57 milliseconds Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:28 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:28 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":349,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:28 volumio volumio[1032]: verbose: CURRENT POSITION 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:28 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:28 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:28 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 140ms Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 134ms Mar 28 19:31:28 volumio volumio[1032]: info: ------------------------------ 133ms Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:28 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:29 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 366. Mar 28 19:31:29 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:29 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:29 volumio go-librespot[9433]: go-librespot daemon starting... Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="app state loaded" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=info msg="zeroconf server listening on port 32841" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="obtained new client token: AACMSU3kyMvaCqppCEoEQWayqOIb85fUdETDSTOvasLsM7ic2nFr5qU9ovZ5wuO8ZX/MoOUOVrBiRerjt0h5jVViYLlmzJ7RUvVBLm5cL1Rk8rSqqzn+Ukk6Lie8Qgxew5x8tn/GF9KalFtVwICegnT+jdRcjj7RYoLn31j3V+SDxImzbfiRU3UoK6a0K8PknKbBqjYU0tdENVNJACKhasX2f9LzjuJmmnsjR/RFmJugHkFcVrB0ILQFfg==" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=debug msg="completed challenge" Mar 28 19:31:29 volumio go-librespot[9433]: time="2026-03-28T19:31:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:30 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:30 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:31 volumio volumio[1032]: info: Removing uri mnt/NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3 from favourites Mar 28 19:31:31 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: mpd , removeFromFavourites Mar 28 19:31:31 volumio volumio[1032]: info: Error : CoreCommandRouter::executeOnPlugin: No method [removeFromFavourites] in plugin mpd Mar 28 19:31:31 volumio volumio[1032]: info: Saving local item favourites Mar 28 19:31:31 volumio volumio[1032]: info: Pushing Favourites {"service":"mpd","uri":"mnt/NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","favourite":false} Mar 28 19:31:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 367. Mar 28 19:31:32 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:32 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:32 volumio go-librespot[9466]: go-librespot daemon starting... Mar 28 19:31:32 volumio go-librespot[9466]: time="2026-03-28T19:31:32+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:32 volumio go-librespot[9466]: time="2026-03-28T19:31:32+01:00" level=debug msg="app state loaded" Mar 28 19:31:32 volumio go-librespot[9466]: time="2026-03-28T19:31:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=info msg="zeroconf server listening on port 33013" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="obtained new client token: AAAC/2+c7nOy5Fz8esCzX22RSAbgmLyMk4YIu5zAqcdB3xM65RlXLq5Fc/t6iSPiiYKcEJVLc7ZSTwNCzSgM3Yy1ROjwafpSd72Sf7QMPS9jbw39fx/lBIVmUqqVsZK5J4u3m2pwoJpL31eV7lWO7Dl9YGblUZ/bT7Peb/3M3j2QMwoYROUVHqNFCDOM5Zd+VSxocJqxHoupIduGHSc5Qqfmm0tQKDXqxq5lqlbfz6Fj0o6DPM+MLX0=" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=debug msg="completed challenge" Mar 28 19:31:33 volumio go-librespot[9466]: time="2026-03-28T19:31:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:33 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:33 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 1360 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand stop took 17 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3 Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand stop took 3 milliseconds Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 5 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand clear took 5 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 3 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 2 milliseconds Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3" Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Punky Reggae Party","artist":"Bob Marley","album":"Babylon By Bus","uri":"NAS/ELEMENTS/Bob Marley - 1978 - babylon by bus/12 - Punky Reggae Party.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: No code Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: 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} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: No code Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: 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} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: No code Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 107ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 98ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 98ms Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 102ms Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3" took 100 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 5ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 4ms Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:34 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 21ms Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand play took 19 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 20ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 19ms Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 4 milliseconds Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: Mar 28 19:31:34 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 10 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 7 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand status took 5 milliseconds Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:34 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:34 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 47ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 81ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 81ms Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 68 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 67 milliseconds Mar 28 19:31:34 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 66 milliseconds Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:34 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:34 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":216,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Stone Free","artist":"Jimi Hendrix","album":"Are You Experienced?","uri":"NAS/ELEMENTS/Jimi Hendrix - 1967 - Are You Experienced/13 Stone Free.mp3","trackType":"mp3"} Mar 28 19:31:34 volumio volumio[1032]: verbose: CURRENT POSITION 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:34 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:34 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:34 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 150ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 145ms Mar 28 19:31:34 volumio volumio[1032]: info: ------------------------------ 145ms Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:34 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 368. Mar 28 19:31:36 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:36 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:36 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:36 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:36 volumio go-librespot[9483]: go-librespot daemon starting... Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="app state loaded" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=info msg="zeroconf server listening on port 42061" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="obtained new client token: AAA2aTkeLCSo88gCzABCahMD7uxIMcyfwltRy1Mf+IgLR8wn+nHQnySs+Jzoc3kWY2zaP+iSd7dgouaSvK5yGkoOAwRZPYSOXqOi2L2Mkk5vZl/ZWjU63olNqZrTnlqfnYoTLryFX5QuJfQd7Kk9TE0qBW8xTXsNjqCmwcbzZkCYUksR713pfwyJqkWkifmd3bJ5SmgZqJdFgVDIk7H2ZZ1xzb9C8iYsxcQ+s4qolr69NmEJS099yP9VqA==" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:36 volumio go-librespot[9483]: time="2026-03-28T19:31:36+01:00" level=debug msg="completed challenge" Mar 28 19:31:37 volumio go-librespot[9483]: time="2026-03-28T19:31:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:39 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:39 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 369. Mar 28 19:31:40 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:40 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:40 volumio go-librespot[9501]: go-librespot daemon starting... Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="app state loaded" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=info msg="zeroconf server listening on port 40803" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="obtained new client token: AAAKUmN/QWCzxiDg0cOpiD2q9iMa1TTgdNeHu+Y1uW9vNr7s3LNPdewE0sFEgiyBVzLmjB756dbDZz0vpM8jg/OnAFSzzF61NAOAv50YTbO51J7sL/gLoIxhi8RRumcaQfDe3EM8piQ23uvLjy0kSReqqUL1Q6FiCyJGZ31+v8wGMb7HEE0r8k6hbz/h1zd7Kb2qUy4yAIjhDM7+iTTPzRATvzDK0SQU2LzwNpANqoEIogQlgB8Eo6whkg==" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=debug msg="completed challenge" Mar 28 19:31:40 volumio go-librespot[9501]: time="2026-03-28T19:31:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:42 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:42 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:44 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 370. Mar 28 19:31:44 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:44 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:44 volumio go-librespot[9530]: go-librespot daemon starting... Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="app state loaded" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=info msg="zeroconf server listening on port 33459" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="obtained new client token: AAB3KNhwC1eSLWsguSOhxmfSl/0HQiZDRBHvCGxM6C2c/kSiKEntE/YEyUApFwrcbTkUOxvbAzDQEEjjX+H1Bn6+CumK2n5iPFUVIb1sDiWEjoVTqsCSWy8dmTU8ggoQBb7pblBZCmk1I9SX9SlyWb+EdIwPlahoj/BHzDTy+b4+echWhM8hXlUPKkjQl4uX2Jwn4DauUMNmw+rE0HM5vwv1snr2/WtLZj/NOoTrLLQzR2PBoA2cUH/cNQ==" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=debug msg="completed challenge" Mar 28 19:31:44 volumio go-librespot[9530]: time="2026-03-28T19:31:44+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:45 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:45 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 371. Mar 28 19:31:47 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:47 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:47 volumio go-librespot[9544]: go-librespot daemon starting... Mar 28 19:31:47 volumio go-librespot[9544]: time="2026-03-28T19:31:47+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:47 volumio go-librespot[9544]: time="2026-03-28T19:31:47+01:00" level=debug msg="app state loaded" Mar 28 19:31:47 volumio go-librespot[9544]: time="2026-03-28T19:31:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=info msg="zeroconf server listening on port 33833" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="obtained new client token: AAAx3g+Mzac4cU14oG1Eqz7JiUVi0GmB/l9AOcLSYo9GpWQ+w3ltjVtA9G44XK/Zbp7jQD6bAnG33ex1+PvEZwTlg9JY7XtkkvjTrThOOnjXgAKda1U/ioBempOs+7MB/qD0eCAWAhECnWdWtrxN+bLr10SCRe0xupsSNtYdxoHMnp+tQcKqIcmf8r7MSkj8HSPYjkVGuEHIFoUc32TZqUp2Gmxpdp8f9ngwHLeNI/h7PRwIgZe7lfg=" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=debug msg="completed challenge" Mar 28 19:31:48 volumio go-librespot[9544]: time="2026-03-28T19:31:48+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:48 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 28 19:31:48 volumio volumio[1032]: info: CURURI: playlists Mar 28 19:31:48 volumio volumio[1032]: info: Listing playlists Mar 28 19:31:48 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:49 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:49 volumio volumio[1032]: info: Preload queue cleared Mar 28 19:31:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 372. Mar 28 19:31:51 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:51 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:51 volumio go-librespot[9573]: go-librespot daemon starting... Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="app state loaded" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=info msg="zeroconf server listening on port 39363" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="obtained new client token: AADkOZiPtumqzElTgvKcMB7IticCx0++KjaGLPu6ggQJRqI8J5tNkpNFOAIE/4S+1yPwVZLJNB1QSel5PuRrRUxP+5pXpaiQc+F1qR/y2de6w7r7GLp5aILj0FOXRdcgSrFbDBgqA/fm5UrCSQPhbti+UAfSNNBy4T3Oq+ai9MJc0XwAHZF1LP12NKsq98G6KJZ3Av6I0nctXD+fEMKu5ndbsJQHGUq0ogVFj92CiCSOeyTih7s1UUmx1Q==" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:51 volumio go-librespot[9573]: time="2026-03-28T19:31:51+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:52 volumio go-librespot[9573]: time="2026-03-28T19:31:52+01:00" level=debug msg="completed challenge" Mar 28 19:31:52 volumio go-librespot[9573]: time="2026-03-28T19:31:52+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:52 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:52 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:55 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 373. Mar 28 19:31:55 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:55 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:55 volumio go-librespot[9587]: go-librespot daemon starting... Mar 28 19:31:55 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="app state loaded" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=info msg="zeroconf server listening on port 35371" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="obtained new client token: AABHaG3xj/l99uc/nyK3rWXrsji2xPN2kjs4pI0JCzQELUgd9kPXx3kldBoWBhtOmCmOFIKHxiIgFBXAaiblDJXhfaN12SpzY1w5tOGVNYf+SAe4kWasqPmuqYEVkiHK6kpzJrCWnPFx1BTAvXGxMgoo8bLADoAUWQGaaWrqDUTlL05tLlN7KvxPYJ3c/lZxdLOPldGrAhHMqd//JjfyMr9RInRo3pO9bGSbJhnPVTZg6ZZ9Kj4NRdy2rQ==" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=debug msg="completed challenge" Mar 28 19:31:55 volumio go-librespot[9587]: time="2026-03-28T19:31:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 3721 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand stop took 33 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3 Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand stop took 4 milliseconds Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 8 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand clear took 7 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 5 milliseconds Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3" Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: 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} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: No code Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: 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} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: No code Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 72ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 72ms Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:31:58 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 93ms Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 90 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3" took 90 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 25ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 24ms Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:31:58 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 104ms Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:31:58 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 25ms Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand play took 23 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 21ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 20ms Mar 28 19:31:58 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 75 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 5 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 3 milliseconds Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: Mar 28 19:31:58 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 14 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 13 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 13 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 12 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 6 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand status took 4 milliseconds Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:58 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:58 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 116ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 72ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 71ms Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 57 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 55 milliseconds Mar 28 19:31:58 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 56 milliseconds Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:58 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:58 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":357,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:31:58 volumio volumio[1032]: verbose: CURRENT POSITION 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:31:58 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:31:58 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:31:58 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 144ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 134ms Mar 28 19:31:58 volumio volumio[1032]: info: ------------------------------ 133ms Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:58 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:31:59 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:31:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 374. Mar 28 19:31:59 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:31:59 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:31:59 volumio go-librespot[9644]: go-librespot daemon starting... Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="app state loaded" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=info msg="zeroconf server listening on port 34841" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="obtained new client token: AAB1aCEMNZiwiy0RBxOVT29/HrThWfR28L569Jkes2mHatabgxWJUN6+cj00V5PmFnGrvAxL0q78Q+cs/1eLUthtbZEGv9S6tF7ymQYjl3LgHCfJUKhl7LiUxdy76yqCLcgaxBoi9zRYeg5zQh/j8WNnRXOL0QobLxOXEnxxkxXHYoymVGEESQtKVjBJWCSQWHDNdacQ7XlQJuaaTTVH6zXsIu/rhfUgbSUEFObUF0ElGD1nlQ8ERsN4Dg==" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="completed keyexchange" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=debug msg="completed challenge" Mar 28 19:31:59 volumio go-librespot[9644]: time="2026-03-28T19:31:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:31:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:31:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 4455 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand stop took 22 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3 Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 17 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand stop took 12 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 9 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 8 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 20 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand clear took 21 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 21 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 21 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3" Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1983","artist":"Lucio Dalla","album":"1983","uri":"NAS/ELEMENTS/Lucio Dalla 1983/01 - 1983.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: No code Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 96ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 86ms Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 154ms Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3" took 151 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 96ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 94ms Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:00 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 191ms Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand play took 188 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 187ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 185ms Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 9 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 14 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 12 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 11 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 11 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 34ms Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: Mar 28 19:32:00 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 17 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 16 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 16 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 11 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand status took 10 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:00 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:00 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:00 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 99ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 94ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 94ms Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 142 milliseconds Mar 28 19:32:00 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 142 milliseconds Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:00 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":145,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:00 volumio volumio[1032]: verbose: CURRENT POSITION 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:00 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:00 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:00 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 199ms Mar 28 19:32:00 volumio volumio[1032]: info: ------------------------------ 198ms Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:00 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:01 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:32:01 volumio volumio[1032]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:32:02 volumio volumio[1032]: info: CoreCommandRouter::volumioNext Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::next Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::stop Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::stPlaybackTimer Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:02 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:02 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::serviceStop Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrack 7583 Mar 28 19:32:02 volumio volumio[1032]: info: CoreCommandRouter::serviceStop Mar 28 19:32:02 volumio volumio[1032]: info: ControllerMpd::stop Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:32:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 28 19:32:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 375. Mar 28 19:32:02 volumio systemd[1]: Stopped go-librespot Daemon. Mar 28 19:32:02 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:02 volumio volumio[1032]: info: Mar 28 19:32:02 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:02 volumio volumio[1032]: info: sendMpdCommand stop took 206 milliseconds Mar 28 19:32:02 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::play index undefined Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::startPlaybackTimer Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::clearAddPlayTracks NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3 Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand stop Mar 28 19:32:02 volumio systemd[1]: Started go-librespot Daemon. Mar 28 19:32:02 volumio volumio[1032]: info: CoreStateMachine::updateTrackBlock Mar 28 19:32:02 volumio volumio[1032]: info: CorePlayQueue::getTrackBlock Mar 28 19:32:02 volumio go-librespot[9678]: go-librespot daemon starting... Mar 28 19:32:02 volumio go-librespot[9678]: time="2026-03-28T19:32:02+01:00" level=info msg="running go-librespot 0.4.0" Mar 28 19:32:02 volumio go-librespot[9678]: time="2026-03-28T19:32:02+01:00" level=debug msg="app state loaded" Mar 28 19:32:02 volumio go-librespot[9678]: time="2026-03-28T19:32:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:32:02 volumio volumio[1032]: info: sendMpdCommand status took 107 milliseconds Mar 28 19:32:02 volumio volumio[1032]: info: sendMpdCommand stop took 100 milliseconds Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand clear Mar 28 19:32:02 volumio volumio[1032]: info: Mar 28 19:32:02 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:02 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:02 volumio volumio[1032]: info: Mar 28 19:32:02 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:02 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:02 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 139 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand clear took 139 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 138 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 137 milliseconds Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand add "NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3" Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Burning Up Time","artist":"The Stranglers","album":"No More Heroes","uri":"NAS/ELEMENTS/The Stranglers - No More Heroes/09 - Burning Up Time.mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: No code Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: 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} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=info msg="zeroconf server listening on port 46575" Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: No code Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: 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} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: No code Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 344ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 234ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 234ms Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="obtained new client token: AAC0ykQlRrQjUkULi5ZNnRgWrf02AXDygQGHig/ezn/NPFIx2187B6IiUhSZzbY9F5HgYYXmmjGm2zbFQa9MFNSGoFRXI7zSHsRjZyojOprJzxzm9bUeBw7SkHeGhc+VfTP5NoCOLb3kUHjXvkZuvcDiPZZZZHb+oXaYGymtlHYT79zSyrOXsIj9r1xHMjdlz2FH/JZMTyfv6wB3IwEmgWk4ucQ1vSomnf7grAhZVkZ7DrP3mQ0itmQ=" Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 19:32:03 volumio volumio[1032]: error: updateQueue error: null Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 196ms Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand add "NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3" took 193 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 97ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 96ms Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand play Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces system playlist update Mar 28 19:32:03 volumio volumio[1032]: info: Ignoring MPD Status Update Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="completed keyexchange" Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=debug msg="completed challenge" Mar 28 19:32:03 volumio go-librespot[9678]: time="2026-03-28T19:32:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Mar 28 19:32:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:32:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 207ms Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand play took 206 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 205ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 202ms Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 37 milliseconds Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 9 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 9 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 7 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 7 milliseconds Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus stop Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 56ms Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: Mar 28 19:32:03 volumio volumio[1032]: ---------------------------- MPD announces state update: player Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::getState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand status Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 46 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 45 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 45 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 39 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand status took 37 milliseconds Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseState Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:03 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:03 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:03 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 132ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 130ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 130ms Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 82 milliseconds Mar 28 19:32:03 volumio volumio[1032]: info: sendMpdCommand playlistinfo took 83 milliseconds Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: verbose: ControllerMpd::parseTrackInfo Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:03 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ControllerMpd::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":409,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","artist":null,"album":null,"uri":"NAS/ELEMENTS/Bob Marley - 1999 - a rebel's dream/13 - Fat Boy Slim - I'm A Rainbow Too (Techno Mix).mp3","trackType":"mp3"} Mar 28 19:32:03 volumio volumio[1032]: verbose: CURRENT POSITION 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState stateService play Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::syncState currentStatus play Mar 28 19:32:03 volumio volumio[1032]: info: Received an update from plugin. extracting info from payload Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: CoreStateMachine::pushState Mar 28 19:32:03 volumio volumio[1032]: info: CorePlayQueue::getTrack 1483 Mar 28 19:32:03 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 170ms Mar 28 19:32:03 volumio volumio[1032]: info: ------------------------------ 168ms Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:03 volumio volumio[1032]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Mar 28 19:32:04 volumio volumio[1032]: info: Initializing connection to go-librespot Websocket Mar 28 19:32:04 volumio volumio[1032]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:32:04 volumio volumio[1032]: TypeError: Cannot read property 'slice' of null Mar 28 19:32:04 volumio volumio[1032]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Mar 28 19:32:04 volumio volumio[1032]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Mar 28 19:32:04 volumio volumio[1032]: at Object.onceWrapper (events.js:422:26) Mar 28 19:32:04 volumio volumio[1032]: at ClientRequest.emit (events.js:315:20) Mar 28 19:32:04 volumio volumio[1032]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:641:27) Mar 28 19:32:04 volumio volumio[1032]: at HTTPParser.parserOnHeadersComplete (_http_common.js:126:17) Mar 28 19:32:04 volumio volumio[1032]: at TLSSocket.socketOnData (_http_client.js:509:22) Mar 28 19:32:04 volumio volumio[1032]: at TLSSocket.emit (events.js:315:20) Mar 28 19:32:04 volumio volumio[1032]: at addChunk (internal/streams/readable.js:309:12) Mar 28 19:32:04 volumio volumio[1032]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 28 19:32:04 volumio volumio[1032]: at TLSSocket.Readable.push (internal/streams/readable.js:223:10) Mar 28 19:32:04 volumio volumio[1032]: at TLSWrap.onStreamRead (internal/stream_base_commons.js:188:23) Mar 28 19:32:04 volumio volumio[1032]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:32:05 volumio sudo[9699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-28 19:31 Mar 28 19:32:05 volumio sudo[9699]: 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="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 05:43:24 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="15d0241b0cd805792809f3ddf4a0fc4e"