-- Logs begin at Sun 2025-05-18 14:39:40 EDT, end at Sun 2025-05-18 16:16:48 EDT. -- May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=info msg="zeroconf server listening on port 33909" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="obtained new client token: AAAA6aXJ5Cj+ktpM/zNao3EHy6DB5l4W/F9PHAALY6FU3MExFAqa8ripNGl8tRs94mL3AlPnwj6LnxMVrKAZ5tKMKpsTf4QNE2vwY6Mq5ivRMH1Z7kIy8ry6JxsWf+XiZzvUFiQnCHmCz3XWfyzJpSLKzqbuNXkZYLcheJ8Y1yc9CnykdETk2ckHY1lbv9E2y5fnOX1FYCkrrwkTv+yLYo17rh4eboQ2w17pjtsvA9a7L3HY1IWPBmw=" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="completed keyexchange" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=debug msg="completed challenge" May 18 16:15:00 volumio-office go-librespot[12398]: time="2025-05-18T16:15:00-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:00 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:00 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:01 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:01 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:01 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:02 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:02 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:03 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:03 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30910. May 18 16:15:03 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:03 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:03 volumio-office go-librespot[12412]: go-librespot daemon starting... May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="app state loaded" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="stored credentials not found" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=info msg="zeroconf server listening on port 37255" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="obtained new client token: AAB+jGwmfuJTnCtPoz+sog+JFB0a1UZok5hZh1p9KaXLC8uCIDbuFPvO22jLT4uHH2S6hA0u6inJk9uiCanMu7qS5ttyn5HwO3rLXf5j8olpjpkOJbINT4/7a19BnhKU9YE/WUTVQeIkhmlcFZ8hKt39jzYdYrm805MQ7UkFiaG+yO3vBVgx0lfBsGzqi8BExLrXgm/GY7MN1FsQsv/Xgmv1Wfhfb32ISPM1mZOX1q5vALB/d/+Kl04LMA==" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="completed keyexchange" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=debug msg="completed challenge" May 18 16:15:03 volumio-office go-librespot[12412]: time="2025-05-18T16:15:03-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:03 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:03 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:05 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:05 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:06 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:06 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30911. May 18 16:15:06 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:06 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:06 volumio-office go-librespot[12428]: go-librespot daemon starting... May 18 16:15:06 volumio-office go-librespot[12428]: time="2025-05-18T16:15:06-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:06 volumio-office go-librespot[12428]: time="2025-05-18T16:15:06-04:00" level=debug msg="app state loaded" May 18 16:15:06 volumio-office go-librespot[12428]: time="2025-05-18T16:15:06-04:00" level=debug msg="stored credentials not found" May 18 16:15:06 volumio-office go-librespot[12428]: time="2025-05-18T16:15:06-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=info msg="zeroconf server listening on port 46437" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="obtained new client token: AADJRzIg+dijh0W7DLLglfDKgMzH9oIA+pTDoI/574uCqGr+igkJcl6BW+xcvvH96PnoJGXki+A+i8X+lmtvrSsfr92fsqMn4x8E0rIQpnH2R8BuGZEdjuZCQNvm+jDpsL1jxqlSGoiwogUOaTjCzsi5psyDBw5CCLURAYB6nrsmbA2u2/OymrUG3qTPtaN0U1i5GRA1xdxBQBcs/wCGGdowLQ41+0zMoH28xt70rQnhFjfX68dm1bk=" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="completed keyexchange" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=debug msg="completed challenge" May 18 16:15:07 volumio-office go-librespot[12428]: time="2025-05-18T16:15:07-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:07 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:07 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:07 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:07 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:07 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:07 volumio-office volumio[1158]: info: May 18 16:15:07 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 2ms May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 2ms May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:07 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:07 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:07 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:07 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":13605967,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Joe Walsh - A Life of Illusion","artist":"crock","album":null,"uri":"http://185.33.21.112:80/crock_mobile_aac","trackType":""} May 18 16:15:07 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:07 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:07 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:07 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":13605967,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Joe Walsh - A Life of Illusion","artist":"crock","album":null,"uri":"http://185.33.21.112:80/crock_mobile_aac","trackType":""} May 18 16:15:07 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:07 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:07 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:07 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":13605967,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Joe Walsh - A Life of Illusion","artist":"crock","album":null,"uri":"http://185.33.21.112:80/crock_mobile_aac","trackType":""} May 18 16:15:07 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:07 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:07 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 10ms May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 10ms May 18 16:15:07 volumio-office volumio[1158]: info: ------------------------------ 10ms May 18 16:15:07 volumio-office volumio[1158]: info: [LastFM] Split composite title into artist: Joe Walsh and title: A Life of Illusion May 18 16:15:07 volumio-office volumio[1158]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:07 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:08 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:08 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:10 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:10 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30912. May 18 16:15:10 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:10 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:10 volumio-office go-librespot[12456]: go-librespot daemon starting... May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="app state loaded" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="stored credentials not found" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=info msg="zeroconf server listening on port 35995" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="obtained new client token: AADimDKc65SpVHquE0AwwaB8YBm/oP1Mear4yyYoPOymS/8z4j0ClfmvQDiO8dejq6XBc9/V2rxuzXhWX30vpiDysxQk0043MnNLBXwoi4lFl+Kjpqfp04z/DRiRBRlF8zDx/MdQGdaoP11P3ZPBDmoAC0+vwhsaeLGilJ3stLMTIiJYN+WUX8Z/km5PMpSZAKF7+lQHP8XLQLASgZYqlc0kK6HZ5kK6dSxIOEnGO3GPV3WCV/5K4t7p3g==" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="completed keyexchange" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=debug msg="completed challenge" May 18 16:15:10 volumio-office go-librespot[12456]: time="2025-05-18T16:15:10-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:10 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:10 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:11 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:11 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:11 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:13 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:13 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30913. May 18 16:15:13 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:13 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:13 volumio-office go-librespot[12470]: go-librespot daemon starting... May 18 16:15:13 volumio-office go-librespot[12470]: time="2025-05-18T16:15:13-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:13 volumio-office go-librespot[12470]: time="2025-05-18T16:15:13-04:00" level=debug msg="app state loaded" May 18 16:15:13 volumio-office go-librespot[12470]: time="2025-05-18T16:15:13-04:00" level=debug msg="stored credentials not found" May 18 16:15:13 volumio-office go-librespot[12470]: time="2025-05-18T16:15:13-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=info msg="zeroconf server listening on port 35367" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="obtained new client token: AAAHnt+aI0hv3O0ua+Tuet9NSW+xj1cqlrvclqoi+ZQd5U2S/xHPzRJkSwiNeiOGM3Py4aeutu+cXY5dApQodGT/BcYuioAo18zFqnVy6wfJe3vXrlpF7MYCHN3qqYAqAQYvgCzdUy1pwGRLF/owMO/tth2GXzB0OfLQ51Dr6mOOHjX1jYTp2x5u1BtlvWrvbCV0YLYj3pJMret3rbPOJmDdGZ8oi0Qghvn7ruoBA2Hd/2uDSaWr7TM=" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="completed keyexchange" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=debug msg="completed challenge" May 18 16:15:14 volumio-office go-librespot[12470]: time="2025-05-18T16:15:14-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:14 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:14 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:14 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:14 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:17 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:17 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30914. May 18 16:15:17 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:17 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:17 volumio-office go-librespot[12490]: go-librespot daemon starting... May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="app state loaded" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="stored credentials not found" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=info msg="zeroconf server listening on port 33099" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="obtained new client token: AADD7kgfOPFpypOqSrNEftinELw/OVa6IwMB3l7FCVCOL2usivfptEk/PoCC1CN/jzQlOgTVUmG+TEf/3EKNZmXks8xr1ef/skqRDbeYnl2qk1EFyqW7VEVjjW71Oy2499TwfM+sXRTy8eXfU3w4AwDnPfKZj0sI8nl1ieO7hi62IhbB39mQygHzvFSPKEHoHom3ae4XYCjG7a8raRhwRbvIZtCRoFocFZlXaeA4KwhfPevx0RNjz9sVFg==" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="completed keyexchange" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=debug msg="completed challenge" May 18 16:15:17 volumio-office go-librespot[12490]: time="2025-05-18T16:15:17-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:17 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:17 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:17 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:17 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:20 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:20 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:20 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:20 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30915. May 18 16:15:20 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:20 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:20 volumio-office go-librespot[12511]: go-librespot daemon starting... May 18 16:15:20 volumio-office go-librespot[12511]: time="2025-05-18T16:15:20-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:20 volumio-office go-librespot[12511]: time="2025-05-18T16:15:20-04:00" level=debug msg="app state loaded" May 18 16:15:20 volumio-office go-librespot[12511]: time="2025-05-18T16:15:20-04:00" level=debug msg="stored credentials not found" May 18 16:15:20 volumio-office go-librespot[12511]: time="2025-05-18T16:15:20-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=info msg="zeroconf server listening on port 43905" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="obtained new client token: AAA4Ins5mdKaTceLTn12MMQ7FO5wwv9qqYSS/0iFdXgug+2TcyER59PK9c+lPMC9HyOqd5L9fm8HDTtdj2tnHjgfSBKBKADs+TOLcXTdcYF5APsalDmjWReixbnpnxmhQ2MSZDJVUMxgMIYWeBIID6dzoN6lfyZbATDKHajiwE259hqRRa+2/o2wE5LFQ1bJbbdmZTb7NB/x3Y3+qzFTF/4060PgZGFQgVqCmlCwAc/ieMi8Wn9rzow=" May 18 16:15:21 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:21 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:21 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="completed keyexchange" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=debug msg="completed challenge" May 18 16:15:21 volumio-office go-librespot[12511]: time="2025-05-18T16:15:21-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:21 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:21 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:23 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:23 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:24 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:24 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30916. May 18 16:15:24 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:24 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:24 volumio-office go-librespot[12528]: go-librespot daemon starting... May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="app state loaded" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="stored credentials not found" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=info msg="zeroconf server listening on port 39845" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="obtained new client token: AAAlWTjYZ6voaLFpTMHa1HC1QvU+aIhcT82f9NtLYs2nHsMhzXRsXiBBqBz2D9wFzU26cSO931+u6b1+GXKccQN7jtZYWaHKhfUFZX8gdP3UDim1so3jMgLGozcK9Eo0dDPya0N8DSJRTmpVMxG5nGMMJ+KjaWqWcYccux8YybxUVnzlXlNdoSAA5QKdh7ZHrAjdn2GQQbgB5oJy03JTBZtCk70xpT9QSweLRQ0h2mSJ26tqOPZwU7XVsg==" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="completed keyexchange" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=debug msg="completed challenge" May 18 16:15:24 volumio-office go-librespot[12528]: time="2025-05-18T16:15:24-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:24 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:24 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:26 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:26 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:27 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:27 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30917. May 18 16:15:27 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:27 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:27 volumio-office go-librespot[12554]: go-librespot daemon starting... May 18 16:15:27 volumio-office go-librespot[12554]: time="2025-05-18T16:15:27-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:27 volumio-office go-librespot[12554]: time="2025-05-18T16:15:27-04:00" level=debug msg="app state loaded" May 18 16:15:27 volumio-office go-librespot[12554]: time="2025-05-18T16:15:27-04:00" level=debug msg="stored credentials not found" May 18 16:15:27 volumio-office go-librespot[12554]: time="2025-05-18T16:15:27-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=info msg="zeroconf server listening on port 38297" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="obtained new client token: AACUJcHMiT0VGOblGaqVQRUyc/HyjpKbTh9nofQpilC9BFYAfPEfplxAor7yumbKzMWeNci5EYqigC1Zr8jtI1j/H/budqKWS+nCHpHwCWyF4gvznjE953c9OY8LU+uWqBIAslit48ATBC4xyDlP72oIDK2QHptWah466U1un+OV7U2v6fjuW4TRENPjbQ6QncW1455+4II2ORBy+Vb44j2xt+PjP8TLtMrBi7yZ/lm7g2LJ1XtI7uY=" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="completed keyexchange" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=debug msg="completed challenge" May 18 16:15:28 volumio-office go-librespot[12554]: time="2025-05-18T16:15:28-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:28 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:28 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:29 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:29 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:31 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:31 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:31 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30918. May 18 16:15:31 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:31 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:31 volumio-office go-librespot[12570]: go-librespot daemon starting... May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="app state loaded" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="stored credentials not found" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=info msg="zeroconf server listening on port 46059" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="obtained new client token: AACj0DO3xnxxPMsh5rVjIFj7S7h0SMyYvFYvztlWYJ0wc/WZiH3tw1quDxl/W9Stw0Zxsv4S6kvgxzsFbGypnBDAo+IrmYZ0lHQpdtyGAiDcFCO2KXoatZTuOP8imjYdYqlaMAxTRlAj2UmRv3x1KHv/kKDbB0XuK9b41AIp18htXP/C2jBFIh5r6dBeT8Cv/enhk1EQGbSEQR8ezYi8o4aD9nXdGXkw8fQer7g4kDbv+WTzbF/J+Y3d9w==" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="completed keyexchange" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=debug msg="completed challenge" May 18 16:15:31 volumio-office go-librespot[12570]: time="2025-05-18T16:15:31-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:31 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:31 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:32 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:32 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:34 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:34 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30919. May 18 16:15:34 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:34 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:34 volumio-office go-librespot[12585]: go-librespot daemon starting... May 18 16:15:34 volumio-office go-librespot[12585]: time="2025-05-18T16:15:34-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:34 volumio-office go-librespot[12585]: time="2025-05-18T16:15:34-04:00" level=debug msg="app state loaded" May 18 16:15:34 volumio-office go-librespot[12585]: time="2025-05-18T16:15:34-04:00" level=debug msg="stored credentials not found" May 18 16:15:34 volumio-office go-librespot[12585]: time="2025-05-18T16:15:34-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=info msg="zeroconf server listening on port 37395" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="obtained new client token: AAD+JkbhHGqcfp3GxeSEQpBGY6NRgY7MlkmaLxdcRP0OmDNHVwFRg2yAQzH90Zi1NAP6BQTd2QFa0KQvM2iIrgIsDOPYBO5Z6D9yhOtITF7wGtY5f3yVT3cUKRa2JX6xkMxiGHD4tKYo1kdEo+0RqSQOfmYcoTNgQYP9z6TMQ7QV3Qgtn3IciceNuNDFhQIzf7h20AFa9hmNnnFc1WivIUp2MrOrKy7elKrUX4YHtCR4OjNmXcVHuRc=" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="completed keyexchange" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=debug msg="completed challenge" May 18 16:15:35 volumio-office go-librespot[12585]: time="2025-05-18T16:15:35-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:35 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:35 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:35 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:35 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:38 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:38 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30920. May 18 16:15:38 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:38 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:38 volumio-office go-librespot[12612]: go-librespot daemon starting... May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="app state loaded" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="stored credentials not found" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=info msg="zeroconf server listening on port 34025" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="obtained new client token: AADjkRyVidNDkzdI8IH+nE5c/mKcANKQKcuExNWW8wbebhs4kCdhk9r+wMX31Cc8SCs+wOPeqmaisXcuJl3C+bsMUAIDYG4QZbcbQaz7F/zSDYaAlObZmjYbcmi70dOttJ+QwS8ecL8Oi5eZIVY12gif5TJ/yuTsXxIveQ9hnwITs/Ae1G74kwqvTFpMYkkpXSXJVIq2j3Pe6sx3GEycd+8YhtcQSODUsd5NcyamURfMyQUlUHaGVOM8rw==" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="completed keyexchange" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=debug msg="completed challenge" May 18 16:15:38 volumio-office go-librespot[12612]: time="2025-05-18T16:15:38-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:38 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:38 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:38 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:38 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: 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":"Joe Walsh - A Life of Illusion","artist":"crock","album":null,"uri":"http://185.33.21.112:80/crock_mobile_aac","trackType":""} May 18 16:15:39 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::play index undefined May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::setConsumeUpdateService undefined May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::startPlaybackTimer May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: [1747599339246] ControllerWebradio::clearAddPlayTrack May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand stop May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 9ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 9ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 9ms May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand stop took 2 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand clear May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand clear took 5 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1807142" May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: error: updateQueue error: null May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 2ms May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1807142" took 255 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::setConsumeUpdateService mpd May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand play May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 255ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 255ms May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand play took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:39 volumio-office volumio[1158]: info: Clearing queue after UPNP request May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::ClearQueue May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::setConsumeUpdateService undefined May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::clearPlayQueue May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::saveQueue May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushQueue May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:39 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:39 volumio-office volumio[1158]: info: May 18 16:15:39 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:39 volumio-office volumio[1158]: error: updateQueue error: null May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 2ms May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: 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} May 18 16:15:39 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: No code May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 5ms May 18 16:15:39 volumio-office volumio[1158]: error: updateQueue error: null May 18 16:15:39 volumio-office volumio[1158]: error: updateQueue error: null May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 5ms May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 5 milliseconds May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 5ms May 18 16:15:39 volumio-office volumio[1158]: info: sendMpdCommand status took 5 milliseconds May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: 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} May 18 16:15:39 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: No code May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: 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} May 18 16:15:39 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus stop May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: No code May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioPushState May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 11ms May 18 16:15:39 volumio-office volumio[1158]: info: ------------------------------ 11ms May 18 16:15:39 volumio-office volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 May 18 16:15:39 volumio-office volumio[1158]: info: Starting UPNP Playback May 18 16:15:39 volumio-office volumio[1158]: info: Preparing playback through UPNP May 18 16:15:39 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:39 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:39 volumio-office volumio[1158]: info: CoreStateMachine::setConsumeUpdateService mpd May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: May 18 16:15:40 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:40 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:40 volumio-office volumio[1158]: info: ------------------------------ 0ms May 18 16:15:41 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:41 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:41 volumio-office volumio[1158]: info: Listing playlists May 18 16:15:41 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:41 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30921. May 18 16:15:41 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:41 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:41 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:41 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:41 volumio-office go-librespot[12634]: go-librespot daemon starting... May 18 16:15:41 volumio-office go-librespot[12634]: time="2025-05-18T16:15:41-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:41 volumio-office go-librespot[12634]: time="2025-05-18T16:15:41-04:00" level=debug msg="app state loaded" May 18 16:15:41 volumio-office go-librespot[12634]: time="2025-05-18T16:15:41-04:00" level=debug msg="stored credentials not found" May 18 16:15:41 volumio-office go-librespot[12634]: time="2025-05-18T16:15:41-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=info msg="zeroconf server listening on port 37835" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="obtained new client token: AAAj+uDSIs91tK7klPHciP79hVZCAfYME5LjUGMWigX06fuUuhn6EpMKr1iC2LoMlwpBYPasN2xtgH0XsMvd2vhUZzBIvjufXUZIHDLUmqj8SIPD6aXH0rVyhF4yp5YPRpxmqWJVBcfuBshqppqigosJuHfwWRYMf+kXGJFuaiWRWKN2oA3KolVjPEZBrC5r6jMMsknN0O4K8VEuAqXpX8kRGJVgHFdVAQ5tnTp879W1Fo5aE/Bjqz4=" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="completed keyexchange" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=debug msg="completed challenge" May 18 16:15:42 volumio-office go-librespot[12634]: time="2025-05-18T16:15:42-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:42 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:42 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:44 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:44 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:45 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30922. May 18 16:15:45 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:45 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:45 volumio-office go-librespot[12686]: go-librespot daemon starting... May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="app state loaded" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="stored credentials not found" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=info msg="zeroconf server listening on port 34031" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="obtained new client token: AAAWja3qMparnh6MNXvWfHybzygTfitXOgtsu5iUWXJXAVEYS+y0Or7K6mqO1U8Q54hCrfGFjBP6BJCOdFQ6KJ+amQmV5Al/PMP7n8zDrGwVk4BksxhPsWaTdm/RcVFfJKNTPdjF7zBb41dPLN8Y4oX5yOoLk9kLujbWFVOxo4/pQ8tMkVKbHmqLu6vg8ekiCd6n3hzWTCdXGeCVYb3M6CMR/PAgjBMV5xVXtK9ZlYMJhEAHpq9s0mxlfg==" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="completed keyexchange" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=debug msg="completed challenge" May 18 16:15:45 volumio-office go-librespot[12686]: time="2025-05-18T16:15:45-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:45 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:45 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:45 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 454 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 453 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 452 milliseconds May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 0 milliseconds May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus stop May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":462,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"243 Kbps","isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:45 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":462,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"255 Kbps","isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:45 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 458ms May 18 16:15:45 volumio-office volumio[1158]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 18 16:15:45 volumio-office volumio[1158]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 456ms May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 456ms May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:45 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces system playlist update May 18 16:15:45 volumio-office volumio[1158]: info: Ignoring MPD Status Update May 18 16:15:45 volumio-office volumio[1158]: info: May 18 16:15:45 volumio-office volumio[1158]: ---------------------------- MPD announces state update: player May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::getState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand status May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 4 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 1ms May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 1 milliseconds May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":966,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"250 Kbps","isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:45 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:45 volumio-office volumio[1158]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 6ms May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 2ms May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand status took 2 milliseconds May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseState May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":966,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"269 Kbps","isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:45 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:45 volumio-office volumio[1158]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 3ms May 18 16:15:45 volumio-office volumio[1158]: info: sendMpdCommand playlistinfo took 1 milliseconds May 18 16:15:45 volumio-office volumio[1158]: verbose: ControllerMpd::parseTrackInfo May 18 16:15:45 volumio-office volumio[1158]: info: ControllerMpd::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::servicePushState May 18 16:15:45 volumio-office volumio[1158]: verbose: In UPNP mode May 18 16:15:45 volumio-office volumio[1158]: verbose: STATE SERVICE {"status":"play","position":0,"seek":966,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"269 Kbps","isStreaming":false,"title":"5f5c87d8ee754fe7bc703da6bc213908.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.3.181:8097/flow/iwiK6u65/uuid:3f61d9e8-130c-7166-4b56-2ccf67020293/5f5c87d8ee754fe7bc703da6bc213908.flac","trackType":"flac"} May 18 16:15:45 volumio-office volumio[1158]: verbose: CURRENT POSITION 0 May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState stateService play May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::syncState currentStatus play May 18 16:15:45 volumio-office volumio[1158]: info: Received an update from plugin. extracting info from payload May 18 16:15:45 volumio-office volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt May 18 16:15:45 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:15:45 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:45 volumio-office volumio[1158]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined May 18 16:15:45 volumio-office volumio[1158]: info: ------------------------------ 4ms May 18 16:15:47 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:47 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:48 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:48 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30923. May 18 16:15:48 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:48 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:48 volumio-office go-librespot[12717]: go-librespot daemon starting... May 18 16:15:48 volumio-office go-librespot[12717]: time="2025-05-18T16:15:48-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:48 volumio-office go-librespot[12717]: time="2025-05-18T16:15:48-04:00" level=debug msg="app state loaded" May 18 16:15:48 volumio-office go-librespot[12717]: time="2025-05-18T16:15:48-04:00" level=debug msg="stored credentials not found" May 18 16:15:48 volumio-office go-librespot[12717]: time="2025-05-18T16:15:48-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=info msg="zeroconf server listening on port 44795" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="obtained new client token: AAACdrIT6aHP9WDc7m6wyJHs5HWVPYAVyE/EB1N4CqF4vtzw1mvGYbl3/s5VGnGB5JMU5P8VB8sNtLp9RftLKE16b+1F+sHMnaPuEGR3Pa9ULvsutmPDWiPCeuAClaQJj5d7eygMjKOmmwxx9aIcso1jLE6xvDzHZhvLIQqatpEbQRzsJzOXu5G1I5+kflE5WCDQTEP27E1RBLg3HY5c8UNl3MGcvWGQLLTcdDbs/SMn0EiHFGovrp4=" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="completed keyexchange" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=debug msg="completed challenge" May 18 16:15:49 volumio-office go-librespot[12717]: time="2025-05-18T16:15:49-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:49 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:49 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:50 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:50 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:51 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:15:51 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:15:51 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:15:51 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:15:51 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:15:51 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:15:51 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:15:51 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:15:51 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:15:51 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:15:51 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:15:51 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:15:51 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:15:51 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:15:51 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:15:51 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:15:51 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:15:51 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:15:51 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:15:52 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:52 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30924. May 18 16:15:52 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:52 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:52 volumio-office go-librespot[12733]: go-librespot daemon starting... May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="app state loaded" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="stored credentials not found" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=info msg="zeroconf server listening on port 32811" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="obtained new client token: AAA7QyBeaqGroIzuDyd9pHAImFSGY6iG7lujGJwM1e9IBD9fzYA7OZDvhHY+Y2T6U3H6a83jOBlfOvhCfq8z+4bG9PbqJwh1hw06iyC6t5xcowQu15u/qnMMFTXUIx1tdtglFbc56HIPQfawdUzaCTKwO8hkYBlwqjsNWJlKRJavGtI+nprnnScR4qdSkpXeUfag5BRPpBIlM9xPSnpAp/dUORffwDV8AO17nVnoed2HOzz6XCNGwF9jcw==" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="completed keyexchange" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=debug msg="completed challenge" May 18 16:15:52 volumio-office go-librespot[12733]: time="2025-05-18T16:15:52-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:52 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:52 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:53 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:53 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:55 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:55 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30925. May 18 16:15:55 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:55 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:55 volumio-office go-librespot[12750]: go-librespot daemon starting... May 18 16:15:55 volumio-office go-librespot[12750]: time="2025-05-18T16:15:55-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:55 volumio-office go-librespot[12750]: time="2025-05-18T16:15:55-04:00" level=debug msg="app state loaded" May 18 16:15:55 volumio-office go-librespot[12750]: time="2025-05-18T16:15:55-04:00" level=debug msg="stored credentials not found" May 18 16:15:55 volumio-office go-librespot[12750]: time="2025-05-18T16:15:55-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=info msg="zeroconf server listening on port 42633" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="obtained new client token: AADE6yjqsPy7vJMWVDK2h7sCr7nQfFzUl0ghjix5loVP9dza2ddkQhF9hnDhlG8rxt5X3AbiuLgEfnTgn6pAYrATgh32yPNfdHb/xJZw5MzRKlRGvg70oqwU6lhLx8kNBUXQ2R9rFDorKEp1c1RZrCYOTqxMKpsxWAwNMdyp8Pu48kQ06wqjZNsctcmQF3n5jwqYy7ud2l93CtHuxBjZ5PC84hKuYt+X0xU1zAHcusgXAZ7OIytFl7I=" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="completed keyexchange" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=debug msg="completed challenge" May 18 16:15:56 volumio-office go-librespot[12750]: time="2025-05-18T16:15:56-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:56 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:56 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:56 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:56 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:15:59 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:15:59 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30926. May 18 16:15:59 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:15:59 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:15:59 volumio-office go-librespot[12775]: go-librespot daemon starting... May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="app state loaded" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="stored credentials not found" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=info msg="zeroconf server listening on port 37027" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="obtained new client token: AADnBaa8H/8s+5bJdj8k56sSMQxeFzu1eo1fQCUfyAdiCD+djBRMs8rzNHgCq5yISS7YOoHDopVmUFZmTLOlVFPcrhualgQTHK6PlBX79UP7BJl7NTDb3ZDbipM0h7w7/tLvJbqI3RcZEuMVJJA0UKAUMzXAqdqYxeA4XsId0ZGAD2QzHowIoGlqUaSrP9gbAGUkCTN0d3sB7zYuEpyx0hGoawfprEuifeJOY+HBdgqm3TdiH4aEZDycQQ==" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="completed keyexchange" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=debug msg="completed challenge" May 18 16:15:59 volumio-office go-librespot[12775]: time="2025-05-18T16:15:59-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:15:59 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:15:59 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:15:59 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:15:59 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:01 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:01 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:01 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:16:01 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:01 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:01 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:16:01 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:01 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:16:01 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:16:01 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:01 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:16:01 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:01 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:01 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:16:01 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:01 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:16:01 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:16:01 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:01 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:01 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:01 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:02 volumio-office volumio[1416]: 100 May 18 16:16:02 volumio-office volumio[1416]: % Total % Received % Xferd Average Speed Time Time Time Current May 18 16:16:02 volumio-office volumio[1416]: Dload Upload Total Spent Left Speed May 18 16:16:02 volumio-office volumio[1158]: info: May 18 16:16:02 volumio-office volumio[1158]: ---------------------------- Client requests Volume 100 May 18 16:16:02 volumio-office volumio[1158]: info: VolumeController::SetAlsaVolume100 May 18 16:16:02 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:02 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:02 volumio-office volumio[1158]: info: CoreStateMachine::pushState May 18 16:16:02 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:02 volumio-office volumio[1158]: (node:1158) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'name' of undefined May 18 16:16:02 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:02 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:02 volumio-office volumio[1158]: at ControllerYTCR.isCurrentService (/data/plugins/music_service/ytcr/dist/index.js:468:95) May 18 16:16:02 volumio-office volumio[1158]: at /data/plugins/music_service/ytcr/dist/index.js:269:22 May 18 16:16:02 volumio-office volumio[1158]: at CoreCommandRouter.callCallback (/volumio/app/index.js:212:9) May 18 16:16:02 volumio-office volumio[1158]: at CoreCommandRouter.volumioupdatevolume (/volumio/app/index.js:141:8) May 18 16:16:02 volumio-office volumio[1158]: at Promise._successFn (/volumio/app/index.js:135:16) May 18 16:16:02 volumio-office volumio[1158]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) May 18 16:16:02 volumio-office volumio[1158]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 18 16:16:02 volumio-office volumio[1158]: (node:1158) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 5413) May 18 16:16:02 volumio-office volumio[1416]: [158B blob data] May 18 16:16:02 volumio-office volumio[1416]: {"time":1747599362264,"response":"volume Success"}100 May 18 16:16:02 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:02 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30927. May 18 16:16:02 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:02 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:02 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:02 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:02 volumio-office go-librespot[12794]: go-librespot daemon starting... May 18 16:16:02 volumio-office go-librespot[12794]: time="2025-05-18T16:16:02-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:02 volumio-office go-librespot[12794]: time="2025-05-18T16:16:02-04:00" level=debug msg="app state loaded" May 18 16:16:02 volumio-office go-librespot[12794]: time="2025-05-18T16:16:02-04:00" level=debug msg="stored credentials not found" May 18 16:16:02 volumio-office go-librespot[12794]: time="2025-05-18T16:16:02-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=info msg="zeroconf server listening on port 37283" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="obtained new client token: AAAgPmIQSJHJq7X56U63RM+FDmeKle8tuIUqHUWNSk0rPSgWLosnUhqWz6eJPkYRJhNbgYn9/Qo/GwPRdZhCn2KPvUezU5q8SncTWgz+iFeUgN5vo67/hFiRdheiMFeM4/JWFcBH05P++OnTSKZbfwbD/SaEHkG8ZkGQ3YRd7KXR/N4EvflK4sDSwcOi+CIQuQSCBhRS+CtAsriekf+eSSXqN9KJAaoGlQAG9sCXJVVKNexcnmgpZG0=" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="completed keyexchange" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=debug msg="completed challenge" May 18 16:16:03 volumio-office go-librespot[12794]: time="2025-05-18T16:16:03-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:03 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:03 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:05 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:05 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:06 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:06 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30928. May 18 16:16:06 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:06 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:06 volumio-office go-librespot[12810]: go-librespot daemon starting... May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="app state loaded" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="stored credentials not found" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=info msg="zeroconf server listening on port 38705" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="obtained new client token: AAATOb7/nalO8tWXz3NjgwAEdPljbx7NLnk7tGsqnpjwkhx/cxLSedmO2eaAE8M/EIFWVIuLa2zsG5C9DXnluc8/s6tsVZHigMXzomrogOsMddZzUN/tsmXphU0rvL3PQw7fW7kp0eJ16Ed2XXaKDIX6wRpIoTBwH3PSeVguFxIOYt/MR2RCkAkqe9zfSo4PQJ+Y0CTqW7JeQPS6OaSecjN1alv68NswTcg+4jriB4MsRndeFv+S08aM4w==" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="completed keyexchange" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=debug msg="completed challenge" May 18 16:16:06 volumio-office go-librespot[12810]: time="2025-05-18T16:16:06-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:06 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:06 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:08 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:08 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:09 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:09 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30929. May 18 16:16:09 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:09 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:09 volumio-office go-librespot[12835]: go-librespot daemon starting... May 18 16:16:09 volumio-office go-librespot[12835]: time="2025-05-18T16:16:09-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:09 volumio-office go-librespot[12835]: time="2025-05-18T16:16:09-04:00" level=debug msg="app state loaded" May 18 16:16:09 volumio-office go-librespot[12835]: time="2025-05-18T16:16:09-04:00" level=debug msg="stored credentials not found" May 18 16:16:09 volumio-office go-librespot[12835]: time="2025-05-18T16:16:09-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=info msg="zeroconf server listening on port 43915" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="obtained new client token: AAB04YTWERHSza5TTd1ke1PUM9cTIrs926fZP7+uazUcTWMP/bCo7b1uCY2jHGcZykiYuJO+hgMCAViCKtMvB7vUi9IOWolrYN8iqlO/1zoB5TESQcTs7OnZqWw3hQZotTQcTVhPlcXdyTD937HyLpFnk5ZeGCn3Ls+0/oG1gqR7UV6fJ41D6G9QuM/RTuUma9ZurErzlG8YYAFxv4oKNOJP699iSE37vxTM8Pl5KS2q4itHjPw7QXk=" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="completed keyexchange" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=debug msg="completed challenge" May 18 16:16:10 volumio-office go-librespot[12835]: time="2025-05-18T16:16:10-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:10 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:10 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:11 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:11 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:11 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:16:11 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:11 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:11 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:16:11 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:11 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:16:11 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:16:11 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:11 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:16:11 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:11 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:11 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:16:11 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:11 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:16:11 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:16:11 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:11 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:11 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:11 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:13 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:13 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30930. May 18 16:16:13 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:13 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:13 volumio-office go-librespot[12851]: go-librespot daemon starting... May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="app state loaded" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="stored credentials not found" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=info msg="zeroconf server listening on port 37993" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="obtained new client token: AAA5JdMQ5jl7FUKjwV1B9MX8LYzlkSV5wSHU3U/FaZTFeVc8IoLpXlRYk7QvfOwrArEn2QlR1UMBPILw9QnJ+s59lDaZ99g3z6TPvjlScdMtWdMemQwfrgpCxO8ngmrhHZyWwdI9K5Q/eGCOJJsWhGNV22zJ82P0smB3zmZmCwkOKYHXb2LADl2lAHNyExa2jTUz3aAPdzOenWKjtZoO7+1ODa42Hu0B74JP2hy69aODnp/2AxYmh2zDCg==" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="completed keyexchange" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=debug msg="completed challenge" May 18 16:16:13 volumio-office go-librespot[12851]: time="2025-05-18T16:16:13-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:13 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:13 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:14 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:14 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:16 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:16 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30931. May 18 16:16:16 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:16 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:16 volumio-office go-librespot[12865]: go-librespot daemon starting... May 18 16:16:16 volumio-office go-librespot[12865]: time="2025-05-18T16:16:16-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:16 volumio-office go-librespot[12865]: time="2025-05-18T16:16:16-04:00" level=debug msg="app state loaded" May 18 16:16:16 volumio-office go-librespot[12865]: time="2025-05-18T16:16:16-04:00" level=debug msg="stored credentials not found" May 18 16:16:16 volumio-office go-librespot[12865]: time="2025-05-18T16:16:16-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=info msg="zeroconf server listening on port 39977" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="obtained new client token: AADeByTKOIasrfxGuRbUd68HYPlXJsuHnymBHBw3TPaH1LMxoNd5kuVw9lBDW20P4id01i7CfO4yqKpL27yZi2ju0/dwYCX5/+43VZk+OVaWGmr5CBALWgcj21ALBgDz+Mfbfc5FSfpc7qAyhoopvPg0sUiwj17EHVLiYHxQcl2KbWGnnskmzPv9nFCphMrt0XU8WZ3+6cyZqyPx9uwuEVHr/K7EBUg4lTuU/o2KmSMq9fONHQEKY2o=" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="completed keyexchange" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=debug msg="completed challenge" May 18 16:16:17 volumio-office go-librespot[12865]: time="2025-05-18T16:16:17-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:17 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:17 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:17 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:17 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:20 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:20 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30932. May 18 16:16:20 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:20 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:20 volumio-office go-librespot[12892]: go-librespot daemon starting... May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="app state loaded" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="stored credentials not found" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=info msg="zeroconf server listening on port 42879" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="obtained new client token: AABk6XvcbnO5e+zgxIk5Q2tMvFX8Ruuu+y6apf47ggO5x3ReGHxhHRTp+9TcEQC8QMasR5v9In+ZPaTw/EwFNnziokH0z7WlLuIRFpZFTkXv+9QqPm+jlqCixggG1P/WLuQ2KdWSJ/yRYQl5wOnpEgH71qD1m/Mm5ulFzDHOWwy/+tufjzGKmmWCC4r8IWWX2yCeZf1NSnmj0alH3eA/WKzpWw2Xlb1K9owAcL27TBlb9x5IeIIDp00WUQ==" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="completed keyexchange" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=debug msg="completed challenge" May 18 16:16:20 volumio-office go-librespot[12892]: time="2025-05-18T16:16:20-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:20 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:20 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:20 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:20 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:21 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:21 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:21 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:16:21 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:21 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:21 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:16:21 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:21 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:16:21 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:16:21 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:21 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:16:21 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:21 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:21 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:16:21 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:21 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:16:21 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:16:21 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:21 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:21 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:21 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:23 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:23 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30933. May 18 16:16:23 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:23 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:23 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:23 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:23 volumio-office go-librespot[12906]: go-librespot daemon starting... May 18 16:16:23 volumio-office go-librespot[12906]: time="2025-05-18T16:16:23-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:23 volumio-office go-librespot[12906]: time="2025-05-18T16:16:23-04:00" level=debug msg="app state loaded" May 18 16:16:23 volumio-office go-librespot[12906]: time="2025-05-18T16:16:23-04:00" level=debug msg="stored credentials not found" May 18 16:16:23 volumio-office go-librespot[12906]: time="2025-05-18T16:16:23-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=info msg="zeroconf server listening on port 45653" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="obtained new client token: AABLe2UmuYbXKU4ucFRMJ5++pw6yrPsra313ryV/BSdJdBujK9zHG5NT7P8wNR1Lfzk3uG0q/0J6FHEuYGAH3Vol5C9yH9aEfB88zXjocM1ED7SmIjjjgAuWVXmypz5iu7jGUnqqDpQ2Jpwk6l7+OKv81gmrcnybp/m0xJaDAszrNHr3YeFF3d4l7B9+DaQW74WRcMuITbdMTOt6lKrhqNI0TGEVEDjHuLHJQOjX2sTmepM8TlM8NVA=" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="completed keyexchange" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=debug msg="completed challenge" May 18 16:16:24 volumio-office go-librespot[12906]: time="2025-05-18T16:16:24-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:24 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:24 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:26 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:26 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:27 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:27 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30934. May 18 16:16:27 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:27 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:27 volumio-office go-librespot[12928]: go-librespot daemon starting... May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="app state loaded" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="stored credentials not found" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=info msg="zeroconf server listening on port 37241" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="obtained new client token: AADUJeO9tXXPlaiMd7HjkYHENNXgdaQSdhlZiWhkpgB2IILhef0d7lYEJIjxV49d8AmPWQ1huyN1CfQn7EhVgjF+yVOL/i+/9wqapF8DIOJzyLn/zpDG037zzwN2eh8N8sCuT9bW8cVR0lHlFWkAqldLpgDk6iKiwZYkCCk3Dd9NRM3U/A3pCUSmiaxesqmlX3FWTn8ecUQwGRqTkfivH7DZIr9kjjD3irVtB9D8dBuk+95ghMryKLXVFA==" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="completed keyexchange" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=debug msg="completed challenge" May 18 16:16:27 volumio-office go-librespot[12928]: time="2025-05-18T16:16:27-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:27 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:27 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:29 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:29 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:30 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:30 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30935. May 18 16:16:30 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:30 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:30 volumio-office go-librespot[12949]: go-librespot daemon starting... May 18 16:16:30 volumio-office go-librespot[12949]: time="2025-05-18T16:16:30-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:30 volumio-office go-librespot[12949]: time="2025-05-18T16:16:30-04:00" level=debug msg="app state loaded" May 18 16:16:30 volumio-office go-librespot[12949]: time="2025-05-18T16:16:30-04:00" level=debug msg="stored credentials not found" May 18 16:16:30 volumio-office go-librespot[12949]: time="2025-05-18T16:16:30-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=info msg="zeroconf server listening on port 34437" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="obtained new client token: AADUEhXPwhkvQsxEZMyRf5YQT3eb1h3pDJjojY87QCL6pc2RGUgDE96zlj0Y3gCk50zZVdGGlLqYqHfvg6/HQ5eILZWO0EG3OU0YvqWApksQku+Amh8Gnnv57PuyMpoYZnXB5/NWhKfnbka7UhU28Mrlp23j3DZxhgci3ryjeAhDL5gjML851PN16XBU2UmSh++EdsOLCara+16ja+NjkOh6pFPD93AL9AwR7m8UCWVECw4sd0G7A9Q=" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:31 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:31 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:31 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:16:31 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:31 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:31 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:16:31 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:31 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:16:31 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:16:31 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:31 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:16:31 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:31 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:31 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:16:31 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:31 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:16:31 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:16:31 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:31 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="completed keyexchange" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=debug msg="completed challenge" May 18 16:16:31 volumio-office go-librespot[12949]: time="2025-05-18T16:16:31-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:31 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:31 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:32 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:32 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:34 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:34 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30936. May 18 16:16:34 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:34 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:34 volumio-office go-librespot[12965]: go-librespot daemon starting... May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="app state loaded" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="stored credentials not found" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=info msg="zeroconf server listening on port 35851" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="obtained new client token: AADDCfjm4DeMqejMs9ux8xS5ObHxc0sZ5PI6Hs/kxUHNC5I/3bEu63PtqMvu8rXAMtuaWGcKryd6e7jfHc5D92kXqKjPjFvbEfgcGmyBgWs0qPlLy4sA40E6cVa8kZxebM5cSMcQjtxdDlHXgGzvV/DG8um9h8r4nq+sbrROuK8FlrTN47t6foKopHfm3nRDEGSjauNH/7yNwf76tbu3bA0+zKTXTeH4eX//YtNE8yLMMN6X7z+RVQ5GNA==" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="completed keyexchange" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=debug msg="completed challenge" May 18 16:16:34 volumio-office go-librespot[12965]: time="2025-05-18T16:16:34-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:34 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:34 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:35 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:35 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:37 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:37 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30937. May 18 16:16:37 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:37 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:37 volumio-office go-librespot[12990]: go-librespot daemon starting... May 18 16:16:37 volumio-office go-librespot[12990]: time="2025-05-18T16:16:37-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:37 volumio-office go-librespot[12990]: time="2025-05-18T16:16:37-04:00" level=debug msg="app state loaded" May 18 16:16:37 volumio-office go-librespot[12990]: time="2025-05-18T16:16:37-04:00" level=debug msg="stored credentials not found" May 18 16:16:37 volumio-office go-librespot[12990]: time="2025-05-18T16:16:37-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=info msg="zeroconf server listening on port 46035" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="obtained new client token: AAAk81O6xl1BUFRITeQmR8ZJiISWGdNDkTcwXHuB1/wRP7jDe0ATFs6kiUf4oZcByn8dwHldzzXRNWjq9Uo82quwXBVvYIYKy00435YExJCb/7YkOuh1Nl4WHRuc5eWqCgRdvwBp+Jxs8Pc/9EBzIth46i3qMFlp2poqt48E7EeILQldv9JL6OMtgaLDvn2p3p1RvIsLQohOFPUVDfQv3X20zbA1zB9fvD632IfS6fuSzP+cnzbd7a4=" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="completed keyexchange" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=debug msg="completed challenge" May 18 16:16:38 volumio-office go-librespot[12990]: time="2025-05-18T16:16:38-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:38 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:38 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:38 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:38 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:41 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:41 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:41 volumio-office volumio[1158]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined May 18 16:16:41 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:41 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:41 volumio-office volumio[1158]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) May 18 16:16:41 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:41 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) May 18 16:16:41 volumio-office volumio[1158]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) May 18 16:16:41 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:41 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:281:22 May 18 16:16:41 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:41 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:41 volumio-office volumio[1158]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) May 18 16:16:41 volumio-office volumio[1158]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) May 18 16:16:41 volumio-office volumio[1158]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) May 18 16:16:41 volumio-office volumio[1158]: at /volumio/node_modules/express/lib/router/index.js:284:7 May 18 16:16:41 volumio-office volumio[1158]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) May 18 16:16:41 volumio-office volumio[1158]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) May 18 16:16:41 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:41 volumio-office volumio[1158]: info: Listing playlists May 18 16:16:41 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:41 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30938. May 18 16:16:41 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:41 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:41 volumio-office go-librespot[13006]: go-librespot daemon starting... May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="app state loaded" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="stored credentials not found" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=info msg="zeroconf server listening on port 37035" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="obtained new client token: AAA/GzxFdparFHQw19o/knGWeDBmOSq26qOwd7O3oKaAii6In0Cflj96LUPJ7IZx02UCeKAG7+3mNXF6Yv/l5Y1EssWq5fxtW3W4S6S9WdwGLWM9uum/TOLrlZGH2zqt3GB5RHm98ObpOKUZGhy1oBVTx4Hd2yToWtaAi2FRgZCVaVmlY5b9wg/owRWO2ovLvLO5mbdurgENFRhJIOLrpe/NICs/4DYv0M5FcAV60HfyzCmBo4aL/cQHzA==" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="completed keyexchange" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=debug msg="completed challenge" May 18 16:16:41 volumio-office go-librespot[13006]: time="2025-05-18T16:16:41-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:41 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:41 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:41 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:41 volumio-office volumio[1158]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:44 volumio-office systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 18 16:16:44 volumio-office systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30939. May 18 16:16:44 volumio-office systemd[1]: Stopped go-librespot Daemon. May 18 16:16:44 volumio-office systemd[1]: Started go-librespot Daemon. May 18 16:16:44 volumio-office go-librespot[13058]: go-librespot daemon starting... May 18 16:16:44 volumio-office go-librespot[13058]: time="2025-05-18T16:16:44-04:00" level=info msg="running go-librespot 0.2.0" May 18 16:16:44 volumio-office go-librespot[13058]: time="2025-05-18T16:16:44-04:00" level=debug msg="app state loaded" May 18 16:16:44 volumio-office go-librespot[13058]: time="2025-05-18T16:16:44-04:00" level=debug msg="stored credentials not found" May 18 16:16:44 volumio-office go-librespot[13058]: time="2025-05-18T16:16:44-04:00" level=info msg="api server listening on 127.0.0.1:9879" May 18 16:16:44 volumio-office volumio[1158]: info: Initializing connection to go-librespot Websocket May 18 16:16:44 volumio-office go-librespot[13058]: time="2025-05-18T16:16:44-04:00" level=debug msg="new websocket client" May 18 16:16:44 volumio-office volumio[1158]: info: Connection to go-librespot Websocket established May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=info msg="zeroconf server listening on port 44325" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="obtained new client token: AAAa2jTViYMRzGw0g+5pSB5rDHztERyI6vzX4ia9bg2j6jB7Tx6YBbiZBCe76huumko2d4L0OmJGB4RQUBscGFycDkuscQn3BIus+FleHkN4sYGAlMQrTa9jA1Bd/isy3wyZ0C2Cw5WlNiLKzac1K5RQaVtGC9lMuZi3HtEG4ntilXvH2QNGtnG55jBhqW2wYsVhpVxWKN/yu8N12+93HFViAJ92XcmVePDmZX447NCNnVplauLpmWQ=" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="completed keyexchange" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=debug msg="completed challenge" May 18 16:16:45 volumio-office go-librespot[13058]: time="2025-05-18T16:16:45-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " May 18 16:16:45 volumio-office systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 18 16:16:45 volumio-office systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 18 16:16:45 volumio-office volumio[1158]: info: Connection to go-librespot Websocket closed May 18 16:16:47 volumio-office volumio[1158]: info: Getting Spotify volume May 18 16:16:47 volumio-office volumio[1158]: (node:1158) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 18 16:16:47 volumio-office volumio[1158]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 18 16:16:47 volumio-office volumio[1158]: (node:1158) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 5414) May 18 16:16:47 volumio-office volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 18 16:16:47 volumio-office volumio[1158]: info: CoreCommandRouter::volumioGetState May 18 16:16:47 volumio-office volumio[1158]: info: CorePlayQueue::getTrack 0 May 18 16:16:47 volumio-office volumio[1158]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 18 16:16:47 volumio-office volumio[1158]: TypeError: Cannot read property 'name' of undefined May 18 16:16:47 volumio-office volumio[1158]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) May 18 16:16:47 volumio-office volumio[1158]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) May 18 16:16:47 volumio-office volumio[1158]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:55:38) May 18 16:16:47 volumio-office volumio[1158]: at Socket.emit (events.js:315:20) May 18 16:16:47 volumio-office volumio[1158]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 18 16:16:47 volumio-office volumio[1158]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 18 16:16:47 volumio-office volumio[1158]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 18 16:16:48 volumio-office sudo[13093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-18 16:15 May 18 16:16:48 volumio-office sudo[13093]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"