-- Logs begin at Mon 2024-11-25 17:15:52 CET, end at Mon 2024-11-25 19:48:07 CET. -- Nov 25 19:47:00 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:00 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:00 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:00 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171027. Nov 25 19:47:00 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:00 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:00 player-number-one go-librespot[12819]: Librespot-go daemon starting... Nov 25 19:47:00 player-number-one go-librespot[12819]: time="2024-11-25T19:47:00+01:00" level=info msg="generated new device id: 556ed0f2f12a9a6c512572ae5d4b7abd44556916" Nov 25 19:47:00 player-number-one go-librespot[12819]: time="2024-11-25T19:47:00+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:00 player-number-one go-librespot[12819]: time="2024-11-25T19:47:00+01:00" level=debug msg="obtained new client token: AADgWAquTOZu+JScxheDxacyI20PN6wCpLfw++orffB83Y5HrN865ohvW5cyGorZIufoAwAzAnofPX13b7L/z52B77vGGextbptldaGaJsaotDi61B5SuOafnQ7/cE6ykV/VsY6hsVwEiEI7i151VOZTTrIdpVCmjo27m+C6K5d82QsRF8CWKtfTF9peeG0n6wDl92GRAljpkb1cBwZqVLW47Jam2JGYa3+VF2D7WMtiX3K6pYGdkK0VnXpKyXDQ" Nov 25 19:47:00 player-number-one go-librespot[12819]: time="2024-11-25T19:47:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:01 player-number-one go-librespot[12819]: time="2024-11-25T19:47:01+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:01 player-number-one go-librespot[12819]: time="2024-11-25T19:47:01+01:00" level=debug msg="completed challenge" Nov 25 19:47:02 player-number-one go-librespot[12819]: time="2024-11-25T19:47:02+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:02 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:02 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:03 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:03 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:05 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:05 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171028. Nov 25 19:47:05 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:05 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:05 player-number-one go-librespot[12831]: Librespot-go daemon starting... Nov 25 19:47:05 player-number-one go-librespot[12831]: time="2024-11-25T19:47:05+01:00" level=info msg="generated new device id: 116605527e7794f702c5f8666749b69e755e08f9" Nov 25 19:47:05 player-number-one go-librespot[12831]: time="2024-11-25T19:47:05+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:05 player-number-one go-librespot[12831]: time="2024-11-25T19:47:05+01:00" level=debug msg="obtained new client token: AAC6x6vMMQWxc7Y2Tut1oUFiIH+jOvlNTikWL8HG8ZsSNarUWxc6bHpQOXO45b1EQ+AHxSM5ucI2omF3ngBDZ/2MnaniXv2KU6yobZ9O6DTMdusFD3LvOwPuTUhmS6d124OQ5ULKhbXNVByBiX5O2/zBe7Sv9WGvBA7H+Ajp3Bv2wPkamxsNsf0wce4qDf3Add0NoWuAcZpMDJcmGje/l+YKL9TIm3IjwpTxccURB+HFMuZ3yPSNc2EmUhvWcdA/" Nov 25 19:47:05 player-number-one go-librespot[12831]: time="2024-11-25T19:47:05+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 19:47:05 player-number-one go-librespot[12831]: time="2024-11-25T19:47:05+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:06 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:06 player-number-one go-librespot[12831]: time="2024-11-25T19:47:06+01:00" level=debug msg="new websocket client" Nov 25 19:47:06 player-number-one volumio[936]: info: Connection to go-librespot Websocket established Nov 25 19:47:06 player-number-one go-librespot[12831]: time="2024-11-25T19:47:06+01:00" level=debug msg="completed challenge" Nov 25 19:47:06 player-number-one go-librespot[12831]: time="2024-11-25T19:47:06+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:06 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:06 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:06 player-number-one volumio[936]: info: Connection to go-librespot Websocket closed Nov 25 19:47:08 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:08 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:08 player-number-one volumio[936]: info: Listing playlists Nov 25 19:47:09 player-number-one volumio[936]: info: Getting Spotify volume Nov 25 19:47:09 player-number-one volumio[936]: (node:936) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:09 player-number-one volumio[936]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 19:47:09 player-number-one volumio[936]: (node:936) 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: 20323) Nov 25 19:47:09 player-number-one volumio[936]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Nov 25 19:47:09 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:09 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:09 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:09 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:09 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:09 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171029. Nov 25 19:47:09 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:09 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:09 player-number-one go-librespot[12865]: Librespot-go daemon starting... Nov 25 19:47:09 player-number-one go-librespot[12865]: time="2024-11-25T19:47:09+01:00" level=info msg="generated new device id: fdcb2ab4bbe8c8dbb7087ebaed9b2574279980ef" Nov 25 19:47:09 player-number-one go-librespot[12865]: time="2024-11-25T19:47:09+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:10 player-number-one go-librespot[12865]: time="2024-11-25T19:47:10+01:00" level=debug msg="obtained new client token: AAD2iCsE3qPD13Cd3wBRQ4jVG+FKrngeKVOPRiqKsBLHAhNj3hUpVgeeSMXVowD/f4XpnOSaGz3Ptt1fhtJJkvO3RkPvFVxcHRwo275lHzu+p4V4KW9x+nQaDt2PvcHhX3AMty0lBfg8gXGDakblV3gN/jcHVlHqHAJR+w0pDanBTEix3iJd1GUNfk6TLQSaoPCCKoTf0asmcg95KiuP7bWsFYTnhgUuiFfj0Rm+EH4rjuwuiQ4he5xh4CreFw==" Nov 25 19:47:10 player-number-one go-librespot[12865]: time="2024-11-25T19:47:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 19:47:10 player-number-one go-librespot[12865]: time="2024-11-25T19:47:10+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:10 player-number-one go-librespot[12865]: time="2024-11-25T19:47:10+01:00" level=debug msg="completed challenge" Nov 25 19:47:10 player-number-one go-librespot[12865]: time="2024-11-25T19:47:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:10 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:10 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:12 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:12 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:14 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:14 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171030. Nov 25 19:47:14 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:14 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:14 player-number-one go-librespot[12876]: Librespot-go daemon starting... Nov 25 19:47:14 player-number-one go-librespot[12876]: time="2024-11-25T19:47:14+01:00" level=info msg="generated new device id: 898c2be3cbd67792decfaeff270113dc5c2d4eba" Nov 25 19:47:14 player-number-one go-librespot[12876]: time="2024-11-25T19:47:14+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:14 player-number-one go-librespot[12876]: time="2024-11-25T19:47:14+01:00" level=debug msg="obtained new client token: AACFigzwyQYTVmVZOyMXGNDNcU01vmlYdWPo2LcovIxKbcrnBW6SZdqLX5I09RV7omDLMHwVP3YNs8yp8TYXUxzCCggUMQrwGMFUoCkJPxKYvMqt9x6E7zuwS+SBrjA2qxgeHjHKjZcVhZe4X15YBpE1V3yRktg8HGBIw/OY+pWLCXvMT6beu9FiupSTSKiuOX6SYgCJm+vhZTQ8znb7XOzp93PWQkgSox6W2PW1bOZwMsQLOvlIz+qyRQmlEmOY" Nov 25 19:47:14 player-number-one go-librespot[12876]: time="2024-11-25T19:47:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:14 player-number-one go-librespot[12876]: time="2024-11-25T19:47:14+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:15 player-number-one go-librespot[12876]: time="2024-11-25T19:47:15+01:00" level=debug msg="completed challenge" Nov 25 19:47:15 player-number-one go-librespot[12876]: time="2024-11-25T19:47:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:15 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:15 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:15 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:15 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:18 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:18 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:18 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:18 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171031. Nov 25 19:47:18 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:18 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:18 player-number-one go-librespot[12898]: Librespot-go daemon starting... Nov 25 19:47:18 player-number-one go-librespot[12898]: time="2024-11-25T19:47:18+01:00" level=info msg="generated new device id: 42c7ba682c9a821b05f9437d1890e661e2f651d4" Nov 25 19:47:18 player-number-one go-librespot[12898]: time="2024-11-25T19:47:18+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:18 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:18 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:19 player-number-one go-librespot[12898]: time="2024-11-25T19:47:19+01:00" level=debug msg="obtained new client token: AAA8ENkBRUH2+31iyxX7lT3gEtgl3vuc9X/bJsXuXaylzp1T7NPx35rV/NZ4OllNmVq1Fq7y4Ta+wsRvio6lkDOwm3nnTJ5cz/1Nl+e6A+djNjzSQAA8C+AlbaaWv94HRc+MTF5R2+ystAJYf/DqR6W+Xj+AroAQkryyzamheUS32qzvCdsv99ca/QXihoTD97lQHUcTYzA0QNOIX8NEi5J0sZVzWUJrkvUeq6mZhmGKn4p4Vk2ZQty5kjcHKA==" Nov 25 19:47:19 player-number-one go-librespot[12898]: time="2024-11-25T19:47:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:19 player-number-one go-librespot[12898]: time="2024-11-25T19:47:19+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:19 player-number-one go-librespot[12898]: time="2024-11-25T19:47:19+01:00" level=debug msg="completed challenge" Nov 25 19:47:19 player-number-one go-librespot[12898]: time="2024-11-25T19:47:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:19 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:19 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:21 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:21 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:23 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:23 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171032. Nov 25 19:47:23 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:23 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:23 player-number-one go-librespot[12920]: Librespot-go daemon starting... Nov 25 19:47:23 player-number-one go-librespot[12920]: time="2024-11-25T19:47:23+01:00" level=info msg="generated new device id: 4d9e77f9227bef2aa737f953d9d7f4381753c4f0" Nov 25 19:47:23 player-number-one go-librespot[12920]: time="2024-11-25T19:47:23+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:23 player-number-one go-librespot[12920]: time="2024-11-25T19:47:23+01:00" level=debug msg="obtained new client token: AACrVSkA/MkEeKaNGOn2rHug4Mk6Z/TH3CRKT8vcGCBQjeVxQLCT5qQDbF7j8Ok0/ki1ab/fGuwY7b6D7N6NHu31UzB+R5Khz7xz2eOoobJOj2yW9Ur0ll41FETeShiWeiFayqKgVlI/GRiCY4wNfHy6JiOpJ7rCoFYn5Bu+sK6V2COT3DVLeGKbqTafNNuxmXssddzB3LZQbozWOSASIrAaminvY1ZNqO/abnC2YeNvAJhl+cxBcDFrg6FnkQtf" Nov 25 19:47:23 player-number-one go-librespot[12920]: time="2024-11-25T19:47:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:23 player-number-one go-librespot[12920]: time="2024-11-25T19:47:23+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:24 player-number-one go-librespot[12920]: time="2024-11-25T19:47:24+01:00" level=debug msg="completed challenge" Nov 25 19:47:24 player-number-one go-librespot[12920]: time="2024-11-25T19:47:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:24 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:24 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:24 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:24 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:24 player-number-one volumiologrotate[563]: ls: cannot access '/var/log/samba/log.wb-PLAYER': No such file or directory Nov 25 19:47:24 player-number-one volumiologrotate[563]: ls: cannot access 'NUMBER': No such file or directory Nov 25 19:47:24 player-number-one volumiologrotate[563]: ls: cannot access 'ONE': No such file or directory Nov 25 19:47:27 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:27 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:27 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:27 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171033. Nov 25 19:47:27 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:27 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:27 player-number-one go-librespot[12972]: Librespot-go daemon starting... Nov 25 19:47:27 player-number-one go-librespot[12972]: time="2024-11-25T19:47:27+01:00" level=info msg="generated new device id: 788aeb788b25e888d23fbc9b29b32b31aba7c129" Nov 25 19:47:27 player-number-one go-librespot[12972]: time="2024-11-25T19:47:27+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:28 player-number-one go-librespot[12972]: time="2024-11-25T19:47:28+01:00" level=debug msg="obtained new client token: AAACRkWoEKlVcd0AEh6U+qJG4K803tqZlFBpHVEKkDkBzUqGdp8fcaNzW1srRdgIHibdHwvQH4f8e/znJl+pX/355ZOuHO8dlB0IyYoEr1RcCbJ2yszvgKtL5RprGRRrAPCkSlT5jNbIGuJ2Ssl2rOf5rB5zoS2F1u8HOmpr04sHibUNBpnOV4Ggkm+rbh9MlUOpJJIL3ZVnob6lBDCgYKyWste2QrGpy5mNdeqvQk20V30xky7kYDH06TryO6EJ" Nov 25 19:47:28 player-number-one go-librespot[12972]: time="2024-11-25T19:47:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:28 player-number-one go-librespot[12972]: time="2024-11-25T19:47:28+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:28 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:28 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:28 player-number-one go-librespot[12972]: time="2024-11-25T19:47:28+01:00" level=debug msg="completed challenge" Nov 25 19:47:28 player-number-one volumio[936]: info: Listing playlists Nov 25 19:47:28 player-number-one volumio[936]: info: Listing playlists Nov 25 19:47:28 player-number-one go-librespot[12972]: time="2024-11-25T19:47:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:28 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:28 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:30 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:30 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:32 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:32 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171034. Nov 25 19:47:32 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:32 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:32 player-number-one go-librespot[13009]: Librespot-go daemon starting... Nov 25 19:47:32 player-number-one go-librespot[13009]: time="2024-11-25T19:47:32+01:00" level=info msg="generated new device id: 5ffed874d6e98f8eff83fdb240e2f73e37adcb5c" Nov 25 19:47:32 player-number-one go-librespot[13009]: time="2024-11-25T19:47:32+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:32 player-number-one go-librespot[13009]: time="2024-11-25T19:47:32+01:00" level=debug msg="obtained new client token: AAB7hVRpFIBBivUVBbw/MxYfe6RFeWNbgv6RfDHwTxhwy0ijM01JguesTiHmK/dXOxtMdUAezljLh/47YQQT7ZqrEtomh4eYx3ZVAsEKbEtTBa4EKGR76pxeuxD2QncACadVoGihF3UYdjxD6ROwOIJYNCZkRA44wggtwpw7u7wKOSadV0X/EoC62m9PpAUoKvKMkp3lOx7EMXGG7VIt5ghvz1IoBfY0d8YZ538kA0g+znxKY1frxFMq2JP30S5A" Nov 25 19:47:32 player-number-one go-librespot[13009]: time="2024-11-25T19:47:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 19:47:32 player-number-one go-librespot[13009]: time="2024-11-25T19:47:32+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:33 player-number-one go-librespot[13009]: time="2024-11-25T19:47:33+01:00" level=debug msg="completed challenge" Nov 25 19:47:33 player-number-one go-librespot[13009]: time="2024-11-25T19:47:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:33 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:33 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:33 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:33 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:36 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:36 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:36 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:36 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171035. Nov 25 19:47:36 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:36 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:36 player-number-one go-librespot[13017]: Librespot-go daemon starting... Nov 25 19:47:36 player-number-one go-librespot[13017]: time="2024-11-25T19:47:36+01:00" level=info msg="generated new device id: b3aad60ba777dcffb6c0f0704220beb9508544f2" Nov 25 19:47:36 player-number-one go-librespot[13017]: time="2024-11-25T19:47:36+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:37 player-number-one go-librespot[13017]: time="2024-11-25T19:47:37+01:00" level=debug msg="obtained new client token: AABhg51e9ifjpPQqBz+JnSxZoNDzA/j2MpkrOHVRlgKKYiAhq7fqCHmwrgqHdVOrXK+K1kCe+0ww/bFG8Y6qBxYqwIwuY7XjtsvmFkVLl31iUzbWMH4FaWdBtYhG6ccfC9YBq59bA4wCQSbE0hgQ+zQ8uEGz3jevGxKtTOEqOclPfauQOG4/xE9NJRL6sqGQl6ANy5h4hdat2yUcCFCJCDq9t11ggRZc+vlG2jCxhGCiQWYISGR8F5XxiIAYJMI/" Nov 25 19:47:37 player-number-one go-librespot[13017]: time="2024-11-25T19:47:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:37 player-number-one go-librespot[13017]: time="2024-11-25T19:47:37+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:37 player-number-one go-librespot[13017]: time="2024-11-25T19:47:37+01:00" level=debug msg="completed challenge" Nov 25 19:47:37 player-number-one go-librespot[13017]: time="2024-11-25T19:47:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:37 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:37 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:38 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:38 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:39 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:39 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:41 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:41 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171036. Nov 25 19:47:41 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:41 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:41 player-number-one go-librespot[13050]: Librespot-go daemon starting... Nov 25 19:47:41 player-number-one go-librespot[13050]: time="2024-11-25T19:47:41+01:00" level=info msg="generated new device id: 7402ea54d9fe6b2202f0cee94365b60c999bf338" Nov 25 19:47:41 player-number-one go-librespot[13050]: time="2024-11-25T19:47:41+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:41 player-number-one go-librespot[13050]: time="2024-11-25T19:47:41+01:00" level=debug msg="obtained new client token: AACuu2xVEMu9iKVkBYat9Bay/4miC2QaoZdsl8TTEr6T/1jphW562XivYoY9d30MQrTnkFxI5bhJeJ2kIkRo5GA4dTxrF9QN4l/dFGOXikODSvRSnXqHWwGkdw6SIYbBsxDiKE/zUC4JI3l17kTv4EIbWE47cbaYb48cIbGnX7uFaQ3xKw3rhcSYY0dXpLtWSD5oTb7JZJ38adKZ7BJcVonoTfCnw4uxyq/gAbOfojCsoPjCYRb4JEsiOy9lpf5+" Nov 25 19:47:41 player-number-one go-librespot[13050]: time="2024-11-25T19:47:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:41 player-number-one go-librespot[13050]: time="2024-11-25T19:47:41+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:42 player-number-one go-librespot[13050]: time="2024-11-25T19:47:42+01:00" level=debug msg="completed challenge" Nov 25 19:47:42 player-number-one go-librespot[13050]: time="2024-11-25T19:47:42+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:42 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:42 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:42 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:42 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:45 player-number-one volumio[936]: info: Clearing queue after UPNP request Nov 25 19:47:45 player-number-one volumio[936]: info: CoreStateMachine::ClearQueue Nov 25 19:47:45 player-number-one volumio[936]: info: CoreStateMachine::stop Nov 25 19:47:45 player-number-one volumio[936]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 25 19:47:45 player-number-one volumio[936]: info: CorePlayQueue::clearPlayQueue Nov 25 19:47:45 player-number-one volumio[936]: info: CorePlayQueue::saveQueue Nov 25 19:47:45 player-number-one volumio[936]: info: CoreCommandRouter::volumioPushState Nov 25 19:47:45 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output update for this device Nov 25 19:47:45 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output Nov 25 19:47:45 player-number-one volumio[936]: info: CoreCommandRouter::volumioPushQueue Nov 25 19:47:45 player-number-one volumio[936]: error: Upnp client error: Error: This socket has been ended by the other party Nov 25 19:47:45 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:45 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:45 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:45 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171037. Nov 25 19:47:45 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:45 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:45 player-number-one go-librespot[13062]: Librespot-go daemon starting... Nov 25 19:47:45 player-number-one go-librespot[13062]: time="2024-11-25T19:47:45+01:00" level=info msg="generated new device id: c07c89ddcea86ab57140f1bb03776d3bf00d9aad" Nov 25 19:47:45 player-number-one go-librespot[13062]: time="2024-11-25T19:47:45+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:46 player-number-one go-librespot[13062]: time="2024-11-25T19:47:46+01:00" level=debug msg="obtained new client token: AAC4tew7dkZkHvAimOHuz6n3QxGGAMSXGvCQGa6brWHgz1Fu+LLLZO6xZ01adQY8rfP84g+wYRWcJIj9z+THz+3XGxE3eUCje43J/iJWF7373MgPZtWKWBjG9rcmw3YTrd2YHhahnEoASWxvNwj916drYYdlDBbEciWMgScPGvFnlr2dkqpCCKl/nTlmaL8VmZyOJJGFjqMbxNKpWFe06XlnGKZuNoLqSyAStNbJarFzk7lGkXrv/YSg9LBvNJrt" Nov 25 19:47:46 player-number-one go-librespot[13062]: time="2024-11-25T19:47:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:46 player-number-one go-librespot[13062]: time="2024-11-25T19:47:46+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:46 player-number-one go-librespot[13062]: time="2024-11-25T19:47:46+01:00" level=debug msg="completed challenge" Nov 25 19:47:46 player-number-one go-librespot[13062]: time="2024-11-25T19:47:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:46 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:46 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:47 player-number-one volumio[936]: info: Starting UPNP Playback Nov 25 19:47:47 player-number-one volumio[936]: info: Preparing playback through UPNP Nov 25 19:47:47 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:47 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:47 player-number-one volumio[936]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 12ms Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 5ms Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 5ms Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 3ms Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: Nov 25 19:47:47 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:47 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 4ms Nov 25 19:47:47 player-number-one volumio[936]: info: ------------------------------ 3ms Nov 25 19:47:48 player-number-one volumio[936]: info: Nov 25 19:47:48 player-number-one volumio[936]: ---------------------------- MPD announces state update: player Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::getState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand status Nov 25 19:47:48 player-number-one volumio[936]: info: Nov 25 19:47:48 player-number-one volumio[936]: ---------------------------- MPD announces state update: player Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand status took 15 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::getState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand status Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand status took 8 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand playlistinfo took 4 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseTrackInfo Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::servicePushState Nov 25 19:47:48 player-number-one volumio[936]: verbose: In UPNP mode Nov 25 19:47:48 player-number-one volumio[936]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Music Assistant","artist":null,"album":null,"uri":"http://192.168.10.146:8097/flow/uuid:cda715cc-ddac-900f-1245-b827ebac4151/8fa8faf6535645c38e527bdc1641e7e5.flac?ts=1732560464","trackType":""} Nov 25 19:47:48 player-number-one volumio[936]: verbose: CURRENT POSITION 0 Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState stateService play Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState currentStatus stop Nov 25 19:47:48 player-number-one volumio[936]: info: ------------------------------ 45ms Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand playlistinfo took 17 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseTrackInfo Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::servicePushState Nov 25 19:47:48 player-number-one volumio[936]: verbose: In UPNP mode Nov 25 19:47:48 player-number-one volumio[936]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Music Assistant","artist":null,"album":null,"uri":"http://192.168.10.146:8097/flow/uuid:cda715cc-ddac-900f-1245-b827ebac4151/8fa8faf6535645c38e527bdc1641e7e5.flac?ts=1732560464","trackType":""} Nov 25 19:47:48 player-number-one volumio[936]: verbose: CURRENT POSITION 0 Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState stateService play Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState currentStatus play Nov 25 19:47:48 player-number-one volumio[936]: info: Received an update from plugin. extracting info from payload Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::volumioPushState Nov 25 19:47:48 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output update for this device Nov 25 19:47:48 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::volumioPushState Nov 25 19:47:48 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output update for this device Nov 25 19:47:48 player-number-one volumio[936]: info: MRS: Pushing multiroomSync output Nov 25 19:47:48 player-number-one volumio[936]: info: ------------------------------ 99ms Nov 25 19:47:48 player-number-one volumio[936]: info: Nov 25 19:47:48 player-number-one volumio[936]: ---------------------------- MPD announces system playlist update Nov 25 19:47:48 player-number-one volumio[936]: info: Ignoring MPD Status Update Nov 25 19:47:48 player-number-one volumio[936]: info: Nov 25 19:47:48 player-number-one volumio[936]: ---------------------------- MPD announces state update: player Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::getState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand status Nov 25 19:47:48 player-number-one volumio[936]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! Music Assistant Nov 25 19:47:48 player-number-one volumio[936]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! Music Assistant Nov 25 19:47:48 player-number-one volumio[936]: info: ------------------------------ 63ms Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand status took 60 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseState Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 25 19:47:48 player-number-one volumio[936]: info: sendMpdCommand playlistinfo took 4 milliseconds Nov 25 19:47:48 player-number-one volumio[936]: verbose: ControllerMpd::parseTrackInfo Nov 25 19:47:48 player-number-one volumio[936]: info: ControllerMpd::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::servicePushState Nov 25 19:47:48 player-number-one volumio[936]: verbose: In UPNP mode Nov 25 19:47:48 player-number-one volumio[936]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1244,"duration":0,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2924 Kbps","isStreaming":false,"title":"8fa8faf6535645c38e527bdc1641e7e5.flac?ts=1732560464","artist":"Music Assistant","album":null,"uri":"http://192.168.10.146:8097/flow/uuid:cda715cc-ddac-900f-1245-b827ebac4151/8fa8faf6535645c38e527bdc1641e7e5.flac?ts=1732560464","trackType":""} Nov 25 19:47:48 player-number-one volumio[936]: verbose: CURRENT POSITION 0 Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState stateService play Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::syncState currentStatus play Nov 25 19:47:48 player-number-one volumio[936]: info: Received an update from plugin. extracting info from payload Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 25 19:47:48 player-number-one volumio[936]: info: CoreStateMachine::pushState Nov 25 19:47:48 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:48 player-number-one volumio[936]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 25 19:47:48 player-number-one volumio[936]: info: ------------------------------ 80ms Nov 25 19:47:48 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:48 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:48 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:48 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:48 player-number-one volumio[936]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Nov 25 19:47:48 player-number-one volumio[936]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 25 19:47:48 player-number-one volumio[936]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 25 19:47:48 player-number-one volumio[936]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Nov 25 19:47:48 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:48 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Nov 25 19:47:48 player-number-one volumio[936]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Nov 25 19:47:48 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:48 player-number-one volumio[936]: at /volumio/node_modules/express/lib/router/index.js:281:22 Nov 25 19:47:48 player-number-one volumio[936]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 25 19:47:48 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 25 19:47:48 player-number-one volumio[936]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Nov 25 19:47:48 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:48 player-number-one volumio[936]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Nov 25 19:47:48 player-number-one volumio[936]: at /volumio/node_modules/express/lib/router/index.js:284:7 Nov 25 19:47:48 player-number-one volumio[936]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 25 19:47:48 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 25 19:47:48 player-number-one volumio[936]: info: Listing playlists Nov 25 19:47:48 player-number-one volumio[936]: info: Listing playlists Nov 25 19:47:50 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:50 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171038. Nov 25 19:47:50 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:50 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:50 player-number-one go-librespot[13106]: Librespot-go daemon starting... Nov 25 19:47:50 player-number-one go-librespot[13106]: time="2024-11-25T19:47:50+01:00" level=info msg="generated new device id: 9f420706d67e5b397edad665c538ed2901c0f6b7" Nov 25 19:47:50 player-number-one go-librespot[13106]: time="2024-11-25T19:47:50+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:50 player-number-one go-librespot[13106]: time="2024-11-25T19:47:50+01:00" level=debug msg="obtained new client token: AAB5Z88GiCxr1GGq/UoUI5FBPbRoLMMufMSt5PLAyk1IkFYGuEJXhUgdEt44W1LfEtfNy7o59cAJN3X9SZPQW2S7QnlnOjE2jGmxGTaj2t6cw4b4Bc+QpQ/jp0oKBp7MBBpNLoAnzjiEkm56ovU+zszn/IAeQ/ph2VVLKBCslxmwG2vJa1kY1fmpOQasS5dmOn5aXD1vssNP7aT1dyfrKiqYSi2JB3tSOgY8AEEDf+/S/PwSL9JXMO8dRq6pknB6" Nov 25 19:47:50 player-number-one go-librespot[13106]: time="2024-11-25T19:47:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:50 player-number-one go-librespot[13106]: time="2024-11-25T19:47:50+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:51 player-number-one go-librespot[13106]: time="2024-11-25T19:47:51+01:00" level=debug msg="completed challenge" Nov 25 19:47:51 player-number-one go-librespot[13106]: time="2024-11-25T19:47:51+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:51 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:51 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:51 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:51 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:54 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:54 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:54 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:54 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171039. Nov 25 19:47:54 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:54 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:54 player-number-one go-librespot[13117]: Librespot-go daemon starting... Nov 25 19:47:54 player-number-one go-librespot[13117]: time="2024-11-25T19:47:54+01:00" level=info msg="generated new device id: 2e88f457731d106bfa9a72ab322193920c2e1760" Nov 25 19:47:54 player-number-one go-librespot[13117]: time="2024-11-25T19:47:54+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:55 player-number-one go-librespot[13117]: time="2024-11-25T19:47:55+01:00" level=debug msg="obtained new client token: AAC6Khxa35fq6x/nFkSDytgvcvJkAdbrY0V6laJzTwpfPQdDprGG3zK7JVowX6U1zG/ZATP0gSlYN6SujymgTXSThMjandwZ0UM51+Vg4FtjIw3cmrZA554PS0vfDu5TtnvpPM2MLfuHnQIaIMiLb/2WAJdui3g5SzTLAmWBYTXQMfi2dS1xx4W/rQcUhy5IIZbwKIEdXJoRxuXxi4nipsR1ISFf+aVqgF0jtf3RbUv2Hl6bKWWtQVFqctMVxQ==" Nov 25 19:47:55 player-number-one go-librespot[13117]: time="2024-11-25T19:47:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:47:55 player-number-one go-librespot[13117]: time="2024-11-25T19:47:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Nov 25 19:47:55 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:55 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:47:57 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:47:57 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:47:58 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:47:58 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171040. Nov 25 19:47:58 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:47:58 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:47:58 player-number-one go-librespot[13140]: Librespot-go daemon starting... Nov 25 19:47:58 player-number-one go-librespot[13140]: time="2024-11-25T19:47:58+01:00" level=info msg="generated new device id: c6e9d0207e6a0f8efa891e953beed91804202785" Nov 25 19:47:58 player-number-one go-librespot[13140]: time="2024-11-25T19:47:58+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:47:58 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:47:58 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:47:58 player-number-one volumio[936]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Nov 25 19:47:58 player-number-one volumio[936]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 25 19:47:58 player-number-one volumio[936]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 25 19:47:58 player-number-one volumio[936]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Nov 25 19:47:58 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:58 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Nov 25 19:47:58 player-number-one volumio[936]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Nov 25 19:47:58 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:58 player-number-one volumio[936]: at /volumio/node_modules/express/lib/router/index.js:281:22 Nov 25 19:47:58 player-number-one volumio[936]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 25 19:47:58 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 25 19:47:58 player-number-one volumio[936]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Nov 25 19:47:58 player-number-one volumio[936]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 25 19:47:58 player-number-one volumio[936]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Nov 25 19:47:58 player-number-one volumio[936]: at /volumio/node_modules/express/lib/router/index.js:284:7 Nov 25 19:47:58 player-number-one volumio[936]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 25 19:47:58 player-number-one volumio[936]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 25 19:47:59 player-number-one go-librespot[13140]: time="2024-11-25T19:47:59+01:00" level=debug msg="obtained new client token: AACdd9Fb3ETGr6j6+Gj2nydyFRT/TPcq8Nbf/bqr68iDDLt031WX+BXOsdfDXph7LJNSMOuWfQnTx+BLbbsRCGPiTR+l1DN2YhikrvDknYqDS8csYvh9u3XHizsjAOXvfLipuccFFk4GB466UQfOFKdRwzKJPgw4PPzBiOX96zS+eYIDZOI34V/acH1LpEl+PSfdpw/t/efukJQta7N8PWHTfQHFckZmxdMeyCmP1apr0xSTtuGh8jER3Xtm+Q==" Nov 25 19:47:59 player-number-one go-librespot[13140]: time="2024-11-25T19:47:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 25 19:47:59 player-number-one go-librespot[13140]: time="2024-11-25T19:47:59+01:00" level=debug msg="completed keyexchange" Nov 25 19:47:59 player-number-one go-librespot[13140]: time="2024-11-25T19:47:59+01:00" level=debug msg="completed challenge" Nov 25 19:47:59 player-number-one go-librespot[13140]: time="2024-11-25T19:47:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:47:59 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:47:59 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:48:00 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:48:00 player-number-one volumio[936]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:48:03 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:48:03 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171041. Nov 25 19:48:03 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:48:03 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:48:03 player-number-one go-librespot[13164]: Librespot-go daemon starting... Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=info msg="generated new device id: d8a41608cb63335b6e3154f441ca3be53d7e100f" Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:48:03 player-number-one volumio[936]: info: Initializing connection to go-librespot Websocket Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=debug msg="new websocket client" Nov 25 19:48:03 player-number-one volumio[936]: info: Connection to go-librespot Websocket established Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=debug msg="obtained new client token: AAA++L4eWRJw3xooeWMb5U0AAE4CiWOPyZ0pAVj38kh+D5/0EevEM9q40czqQmN1eWjhFoNS6e3ZzJxHebOaRUL8abYEeVL5F/9CXuEU9UuGh+E2p0ST5Ecb2bccbKrpxeV1fFG+WLdnOaW25v+3zsDC/vvM+K+zPlYOnF1tk+3LvhgJhErMFUZRJW3I1ltdfkIm7jrppdcHRnrpScORDiV0pMCc3skrEz2H9oJK6DpCfCyLWmC/xdY2dAwbYkHK" Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 25 19:48:03 player-number-one go-librespot[13164]: time="2024-11-25T19:48:03+01:00" level=debug msg="completed keyexchange" Nov 25 19:48:04 player-number-one go-librespot[13164]: time="2024-11-25T19:48:04+01:00" level=debug msg="completed challenge" Nov 25 19:48:04 player-number-one go-librespot[13164]: time="2024-11-25T19:48:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 19:48:04 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 19:48:04 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 19:48:04 player-number-one volumio[936]: info: Connection to go-librespot Websocket closed Nov 25 19:48:06 player-number-one volumio[936]: info: Getting Spotify volume Nov 25 19:48:06 player-number-one volumio[936]: (node:936) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 19:48:06 player-number-one volumio[936]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 25 19:48:06 player-number-one volumio[936]: (node:936) 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: 20324) Nov 25 19:48:06 player-number-one volumio[936]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Nov 25 19:48:06 player-number-one volumio[936]: info: CoreCommandRouter::volumioGetState Nov 25 19:48:06 player-number-one volumio[936]: info: CorePlayQueue::getTrack 0 Nov 25 19:48:06 player-number-one volumio[936]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 19:48:06 player-number-one volumio[936]: TypeError: Cannot read property 'name' of undefined Nov 25 19:48:06 player-number-one volumio[936]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 25 19:48:06 player-number-one volumio[936]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 25 19:48:06 player-number-one volumio[936]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Nov 25 19:48:06 player-number-one volumio[936]: at Socket.emit (events.js:315:20) Nov 25 19:48:06 player-number-one volumio[936]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 25 19:48:06 player-number-one volumio[936]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 25 19:48:06 player-number-one volumio[936]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 19:48:07 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 19:48:07 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171042. Nov 25 19:48:07 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 25 19:48:07 player-number-one systemd[1]: Started go-librespot Daemon. Nov 25 19:48:07 player-number-one go-librespot[13180]: Librespot-go daemon starting... Nov 25 19:48:07 player-number-one go-librespot[13180]: time="2024-11-25T19:48:07+01:00" level=info msg="generated new device id: 08c441b1d9fb3a6f0533557a4a2ba593ec8c0eb6" Nov 25 19:48:07 player-number-one go-librespot[13180]: time="2024-11-25T19:48:07+01:00" level=debug msg="stored credentials found for olterman" Nov 25 19:48:07 player-number-one sudo[13189]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-25 19:47 Nov 25 19:48:07 player-number-one sudo[13189]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"