-- Logs begin at Thu 2024-07-18 13:38:53 CST, end at Thu 2024-07-18 14:59:47 CST. --
Jul 18 14:58:00 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:00 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:00 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:00 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:01 volumio1 volumio[14615]: info: MyVolumio login type: Token
Jul 18 14:58:02 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:02 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71.
Jul 18 14:58:02 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:02 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:02 volumio1 go-librespot[15859]: Librespot-go daemon starting...
Jul 18 14:58:02 volumio1 go-librespot[15859]: time="2024-07-18T14:58:02+08:00" level=info msg="generated new device id: c92ae67e9b7cfad668a6f8ae86a07e44f391a228"
Jul 18 14:58:02 volumio1 go-librespot[15859]: time="2024-07-18T14:58:02+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:02 volumio1 go-librespot[15859]: time="2024-07-18T14:58:02+08:00" level=debug msg="obtained new client token: AADGagmNWH5vhHbD38jauf3Lf5Yp/P2F+DEXZbj3Gc1QxFKx5N+KqGkW0RrZPfly/LiX0NAZ9bn29jiq9PXdVbocalhC0wsIIf88VO9xBCLBuL6PmuLYNpWcYoWqQ5XfOpnMsJ7wKjPgzy8esVHAYXu/NG2yAIFBJDw73MkDxW+MNLCIAh84xQ3QrU9KzFs8jcrs+YhY35y1ZLkPk8gxJDOcQE1D94q8x9yoF/LFLuetk2qvrNkfpmHmfZfc3A=="
Jul 18 14:58:02 volumio1 go-librespot[15859]: time="2024-07-18T14:58:02+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:02 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:02 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:03 volumio1 go-librespot[15859]: time="2024-07-18T14:58:03+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:03 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:03 volumio1 go-librespot[15859]: time="2024-07-18T14:58:03+08:00" level=debug msg="new websocket client"
Jul 18 14:58:03 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:58:03 volumio1 go-librespot[15859]: time="2024-07-18T14:58:03+08:00" level=debug msg="completed challenge"
Jul 18 14:58:03 volumio1 go-librespot[15859]: time="2024-07-18T14:58:03+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:03 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:03 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:03 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:58:04 volumio1 volumio[14615]: info:
Jul 18 14:58:04 volumio1 volumio[14615]: ---------------------------- Client requests Volume 95
Jul 18 14:58:04 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume95
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:04 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 95
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 100
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 95
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:04 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 95
Jul 18 14:58:04 volumio1 volumio[14615]: info:
Jul 18 14:58:04 volumio1 volumio[14615]: ---------------------------- Client requests Volume 90
Jul 18 14:58:04 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume90
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:04 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 95
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 90
Jul 18 14:58:04 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:04 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 90
Jul 18 14:58:04 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:04 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:05 volumio1 volumio[14615]: info:
Jul 18 14:58:05 volumio1 volumio[14615]: ---------------------------- Client requests Volume 85
Jul 18 14:58:05 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume85
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:05 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 90
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 85
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:05 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 85
Jul 18 14:58:05 volumio1 volumio[14615]: info:
Jul 18 14:58:05 volumio1 volumio[14615]: ---------------------------- Client requests Volume 80
Jul 18 14:58:05 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume80
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:05 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 85
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 80
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:05 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 80
Jul 18 14:58:05 volumio1 volumio[14615]: info:
Jul 18 14:58:05 volumio1 volumio[14615]: ---------------------------- Client requests Volume 75
Jul 18 14:58:05 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume75
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:05 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 80
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 75
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:05 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 75
Jul 18 14:58:05 volumio1 volumio[14615]: info:
Jul 18 14:58:05 volumio1 volumio[14615]: ---------------------------- Client requests Volume 70
Jul 18 14:58:05 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume70
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:05 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:05 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 75
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 70
Jul 18 14:58:05 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:05 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 70
Jul 18 14:58:06 volumio1 volumio[14615]: info:
Jul 18 14:58:06 volumio1 volumio[14615]: ---------------------------- Client requests Volume 65
Jul 18 14:58:06 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume65
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 65
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 70
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 65
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:06 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 65
Jul 18 14:58:06 volumio1 volumio[14615]: info:
Jul 18 14:58:06 volumio1 volumio[14615]: ---------------------------- Client requests Volume 60
Jul 18 14:58:06 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume60
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 65
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 60
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:06 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 60
Jul 18 14:58:06 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:58:06 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:06 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:58:06 volumio1 volumio[14615]: (node:14615) 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: 34)
Jul 18 14:58:06 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Jul 18 14:58:06 volumio1 volumio[14615]: info:
Jul 18 14:58:06 volumio1 volumio[14615]: ---------------------------- Client requests Volume 55
Jul 18 14:58:06 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume55
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 60
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 55
Jul 18 14:58:06 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:06 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 55
Jul 18 14:58:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:06 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:06 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:07 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:07 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72.
Jul 18 14:58:07 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:07 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:07 volumio1 go-librespot[15876]: Librespot-go daemon starting...
Jul 18 14:58:07 volumio1 go-librespot[15876]: time="2024-07-18T14:58:07+08:00" level=info msg="generated new device id: 9331cae1c901a30c28edaf53997b9651a45d2eb2"
Jul 18 14:58:07 volumio1 go-librespot[15876]: time="2024-07-18T14:58:07+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:07 volumio1 go-librespot[15876]: time="2024-07-18T14:58:07+08:00" level=debug msg="obtained new client token: AADkev3Nsz4NLAH3vjcmSliRTKm2a0mYxnp4FrfjCn8PUDoBu2JOu1Ik6iPSZJhKFlkvZUhbCJqtFtFl3EwQS7hTY3sfD/akqkRumXeYCMe3GB11qPfozTGGWqoPk9PjGv32+fASUVjUjqO/NXUtqq3cUb3lHoHzWsGyGP6wDleBq3sug1QgVfU4Pb327gZp0+4sqYNkcSha71sL4IzU8zUNGclP+9hcmYdhew9LhpdSH7VvvCtS1V0YQyc4zw=="
Jul 18 14:58:07 volumio1 go-librespot[15876]: time="2024-07-18T14:58:07+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:08 volumio1 volumio[14615]: info:
Jul 18 14:58:08 volumio1 volumio[14615]: ---------------------------- Client requests Volume 50
Jul 18 14:58:08 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume50
Jul 18 14:58:08 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:08 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:08 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:08 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:08 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50
Jul 18 14:58:08 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 55
Jul 18 14:58:08 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 50
Jul 18 14:58:08 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:08 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 50
Jul 18 14:58:08 volumio1 go-librespot[15876]: time="2024-07-18T14:58:08+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:08 volumio1 go-librespot[15876]: time="2024-07-18T14:58:08+08:00" level=debug msg="completed challenge"
Jul 18 14:58:08 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:08 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:09 volumio1 go-librespot[15876]: time="2024-07-18T14:58:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:09 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:09 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:09 volumio1 volumio[14615]: SPOTIFY: SETTING SPOTIFY VOLUME 50
Jul 18 14:58:09 volumio1 volumio[14615]: info: Sending Spotify command with payload to local API: /player/volume
Jul 18 14:58:09 volumio1 volumio[14615]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:09 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:09 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:10 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:10 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:12 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:12 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73.
Jul 18 14:58:12 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:12 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:12 volumio1 go-librespot[15887]: Librespot-go daemon starting...
Jul 18 14:58:12 volumio1 go-librespot[15887]: time="2024-07-18T14:58:12+08:00" level=info msg="generated new device id: cfe0a6fdd1263a2f17b42a251cb99b9bfe6f4804"
Jul 18 14:58:12 volumio1 go-librespot[15887]: time="2024-07-18T14:58:12+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:12 volumio1 go-librespot[15887]: time="2024-07-18T14:58:12+08:00" level=debug msg="obtained new client token: AAAPTTbqaR0LwWXC/qw8oa6esNcumJV2F07ZNioRGmNVMfB4IBSNur0Z0YCBJzqFXgBjJXE+6ZX6CFT21y4n9Y5Rh200xuXarG+gEAUYrvdMvIgNKaShvfvS3GX/FdNn+hz/3UEkEaKwdvgIFl5tMkR7C45nS+f53/M+oZ4tW/4SGRFtha+uLqg802qVWlpjhFwzbpgkEWB6EccepkJtKx8C8uP60C10Y2pHMZ22txUAQkVCn5YQZbIjIaMXTA=="
Jul 18 14:58:12 volumio1 go-librespot[15887]: time="2024-07-18T14:58:12+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:12 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:12 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:12 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:12 volumio1 go-librespot[15887]: time="2024-07-18T14:58:12+08:00" level=debug msg="new websocket client"
Jul 18 14:58:12 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:58:13 volumio1 go-librespot[15887]: time="2024-07-18T14:58:13+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:13 volumio1 go-librespot[15887]: time="2024-07-18T14:58:13+08:00" level=debug msg="completed challenge"
Jul 18 14:58:13 volumio1 go-librespot[15887]: time="2024-07-18T14:58:13+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:13 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:13 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:13 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:58:14 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:14 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:15 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:58:15 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:15 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:58:15 volumio1 volumio[14615]: (node:14615) 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: 35)
Jul 18 14:58:16 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:58:16 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:16 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:16 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50
Jul 18 14:58:16 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:16 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:16 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:16 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:16 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:16 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74.
Jul 18 14:58:16 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:16 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:16 volumio1 go-librespot[15895]: Librespot-go daemon starting...
Jul 18 14:58:16 volumio1 go-librespot[15895]: time="2024-07-18T14:58:16+08:00" level=info msg="generated new device id: f14988058457aa3483cd9453c4d49353f5ea3bc1"
Jul 18 14:58:16 volumio1 go-librespot[15895]: time="2024-07-18T14:58:16+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:17 volumio1 go-librespot[15895]: time="2024-07-18T14:58:17+08:00" level=debug msg="obtained new client token: AADit1eimyU3XJy9qj4SGQ00jIe7ixh56DQvmp/JWFBF8kqfFAVjDaktWmdF6SZFZb2wQXedUtTLhQpZijadGGebN02wSBoivVhCYIkWOBYN/XOLZuspKHbVd0pUKDl03SPyyGXzMlX5OjNGGRO/nUNZBKYgQ7m2EXRRJd9tuwMuK6AwsihmFsFgI6HtHnO1qwDJ2WvSnRZVHw2FZbG2omnBkztZhL+/VjHD6nMYvMyfqdB76HUohgLjYsV8YA=="
Jul 18 14:58:17 volumio1 go-librespot[15895]: time="2024-07-18T14:58:17+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:58:17 volumio1 go-librespot[15895]: time="2024-07-18T14:58:17+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:18 volumio1 go-librespot[15895]: time="2024-07-18T14:58:18+08:00" level=debug msg="completed challenge"
Jul 18 14:58:18 volumio1 go-librespot[15895]: time="2024-07-18T14:58:18+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:18 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:18 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:18 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:18 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:19 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:19 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:20 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:20 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:21 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:21 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75.
Jul 18 14:58:21 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:21 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:21 volumio1 go-librespot[15944]: Librespot-go daemon starting...
Jul 18 14:58:21 volumio1 go-librespot[15944]: time="2024-07-18T14:58:21+08:00" level=info msg="generated new device id: 6cb2ed0376571104ed1daaf57bac8929ef107dee"
Jul 18 14:58:21 volumio1 go-librespot[15944]: time="2024-07-18T14:58:21+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:22 volumio1 go-librespot[15944]: time="2024-07-18T14:58:22+08:00" level=debug msg="obtained new client token: AABSO+luB7g+pRPMtIdqaSgLC/jmcKtkIzdsscOn3sSHCX+ewZ2rzm328jpkSCcLOf9YdrYJNtxjggRXL5v/bCtJGeanPXH2tFMdyjKR5g5dTaHGWMlHTSfkJs90eaZRMnYWNbdiFcStPTmCdpVlFHVhEVEVj9XbMmyYI8X1gbVkQKK9BLU0iaU3c1QZOjVTb/0UKlFslCgsj9/b7BPa+G3TUGh8c5Whfet3U2/vakb+ZRhUhVZud3wSm+MIUQ=="
Jul 18 14:58:22 volumio1 go-librespot[15944]: time="2024-07-18T14:58:22+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:22 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:22 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:22 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:22 volumio1 go-librespot[15944]: time="2024-07-18T14:58:22+08:00" level=debug msg="new websocket client"
Jul 18 14:58:22 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:58:22 volumio1 go-librespot[15944]: time="2024-07-18T14:58:22+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:23 volumio1 go-librespot[15944]: time="2024-07-18T14:58:23+08:00" level=debug msg="completed challenge"
Jul 18 14:58:23 volumio1 go-librespot[15944]: time="2024-07-18T14:58:23+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:23 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:23 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:23 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:58:24 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:24 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:25 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:58:25 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:25 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:58:25 volumio1 volumio[14615]: (node:14615) 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: 36)
Jul 18 14:58:25 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:58:25 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:25 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:25 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50
Jul 18 14:58:26 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:26 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:26 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76.
Jul 18 14:58:26 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:26 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:26 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:26 volumio1 go-librespot[15952]: Librespot-go daemon starting...
Jul 18 14:58:26 volumio1 go-librespot[15952]: time="2024-07-18T14:58:26+08:00" level=info msg="generated new device id: ea2324a0b0a0b35956f0862f341f80e3d1e57103"
Jul 18 14:58:26 volumio1 go-librespot[15952]: time="2024-07-18T14:58:26+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:26 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:26 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:27 volumio1 go-librespot[15952]: time="2024-07-18T14:58:27+08:00" level=debug msg="obtained new client token: AAAj6ugnnL8baEi5h5nUttVEeT7SX3IGACPeqzY28EbCHwXY4NiHY9GgaF5/uepxLOtGawaWcibv3IP68Od98sA/WP5aB9FVeVcVGIoRYUNHkhHg4rtIrQTBTPfMwNhRCeDWymHyr4Ei4dWB/EEjBDr6nVpjCFO+2XSpiCrU5WAyTocPBkh7ol2+F4lQBJs3KKsMZTGKBKJToZ+8FGjh86ICnZhdVUp2Cx0WLKHVW++xptZlq/gTL3UW+YI="
Jul 18 14:58:27 volumio1 go-librespot[15952]: time="2024-07-18T14:58:27+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:27 volumio1 go-librespot[15952]: time="2024-07-18T14:58:27+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:28 volumio1 go-librespot[15952]: time="2024-07-18T14:58:28+08:00" level=debug msg="completed challenge"
Jul 18 14:58:28 volumio1 go-librespot[15952]: time="2024-07-18T14:58:28+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:28 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:28 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:28 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:28 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:29 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:29 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:30 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:30 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:31 volumio1 volumio[14615]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred.
Jul 18 14:58:31 volumio1 volumio[14615]: info: Retrying Login Due to Network Error
Jul 18 14:58:31 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:31 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77.
Jul 18 14:58:31 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:31 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:31 volumio1 go-librespot[15961]: Librespot-go daemon starting...
Jul 18 14:58:31 volumio1 go-librespot[15961]: time="2024-07-18T14:58:31+08:00" level=info msg="generated new device id: 02a68669ab26325ec0c4ad8267fe741c6ebbda37"
Jul 18 14:58:31 volumio1 go-librespot[15961]: time="2024-07-18T14:58:31+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:32 volumio1 go-librespot[15961]: time="2024-07-18T14:58:32+08:00" level=debug msg="obtained new client token: AACGtaePWrJ06vSTzD9D5jBr3En6EEEQl9DUclSghDDRa5Ym5wT3ARCDje5Vk8vvcj2UDBuJhjKfXOSw/TZ230fwxKtMkTV6EWU3qlPZr8gbKN3nFw96KrjuWS4kCESEL+wRuztJIeBGuzSk834Gw1EC/9dNo8MvOtP3ndzoPNvTBezKEeRgTsjEgwZ2K029bPsr9+YOUO0FS9dyTRPsEKvpeMHMv5pe2Yfb0zKF5vT08Rd8gNMbk8C0ZgI="
Jul 18 14:58:32 volumio1 go-librespot[15961]: time="2024-07-18T14:58:32+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:58:32 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:32 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume49
Jul 18 14:58:32 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:32 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:32 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:32 volumio1 go-librespot[15961]: time="2024-07-18T14:58:32+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:32 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:32 volumio1 go-librespot[15961]: time="2024-07-18T14:58:32+08:00" level=debug msg="new websocket client"
Jul 18 14:58:32 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49
Jul 18 14:58:32 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 50
Jul 18 14:58:32 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 49
Jul 18 14:58:32 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: false
Jul 18 14:58:32 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:58:32 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:32 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:33 volumio1 go-librespot[15961]: time="2024-07-18T14:58:33+08:00" level=debug msg="completed challenge"
Jul 18 14:58:33 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume100
Jul 18 14:58:33 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:33 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:33 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:33 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:33 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Jul 18 14:58:33 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 50
Jul 18 14:58:33 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 100
Jul 18 14:58:33 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:33 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 100
Jul 18 14:58:33 volumio1 go-librespot[15961]: time="2024-07-18T14:58:33+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:33 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:33 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:33 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:58:34 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:34 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:34 volumio1 volumio[14615]: SPOTIFY: SETTING SPOTIFY VOLUME 100
Jul 18 14:58:34 volumio1 volumio[14615]: info: Sending Spotify command with payload to local API: /player/volume
Jul 18 14:58:34 volumio1 volumio[14615]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:35 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:58:35 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:35 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:58:35 volumio1 volumio[14615]: (node:14615) 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: 37)
Jul 18 14:58:35 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:58:35 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:35 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:35 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Jul 18 14:58:36 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:36 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:36 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:36 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78.
Jul 18 14:58:36 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:36 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:36 volumio1 go-librespot[15971]: Librespot-go daemon starting...
Jul 18 14:58:36 volumio1 go-librespot[15971]: time="2024-07-18T14:58:36+08:00" level=info msg="generated new device id: 6ffed5c672943cb13e95099325b7686a427a8ceb"
Jul 18 14:58:36 volumio1 go-librespot[15971]: time="2024-07-18T14:58:36+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:36 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:36 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:37 volumio1 go-librespot[15971]: time="2024-07-18T14:58:37+08:00" level=debug msg="obtained new client token: AABGPcIvotbGvtz9Zp606PlIDX3+gnG1V3KeoIxAj1qgNyKWAUEOiK7kXSmr8ZMHOca9Vg4PYcCFtVp47ahOyHkp9h45h/TS9TemMGyc9c86L5NKBZXJgoKT6oC3EvdUT7bWuwXa6byRma3+trCSTSy+v0IVRpOr5WnaRJXryvLB7MQJ8pbixhAw9vbIIeI7TOwG5OJajm0DBAdLq2a0gOd7D9SW51XlARkaqRvkA8Dj6/p3kHRg9sGm3kE="
Jul 18 14:58:37 volumio1 go-librespot[15971]: time="2024-07-18T14:58:37+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:58:37 volumio1 go-librespot[15971]: time="2024-07-18T14:58:37+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:37 volumio1 volumio[14615]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object]
Jul 18 14:58:37 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset
Jul 18 14:58:37 volumio1 volumio[14615]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false
Jul 18 14:58:38 volumio1 go-librespot[15971]: time="2024-07-18T14:58:38+08:00" level=debug msg="completed challenge"
Jul 18 14:58:38 volumio1 go-librespot[15971]: time="2024-07-18T14:58:38+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:38 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:38 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:38 volumio1 volumio[14615]: info: FusionDsp - If filter freq >samplerate/2 then disable it
Jul 18 14:58:38 volumio1 volumio[14615]: info: FusionDsp - Effects disabled
Jul 18 14:58:38 volumio1 volumio[14615]: info: FusionDsp - {"Reload":{"result":"Ok"}}
Jul 18 14:58:38 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:58:38 volumio1 volumio[14615]: info: CoreCommandRouter::Close All Modals sent
Jul 18 14:58:39 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:39 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:39 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:39 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:40 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:40 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:41 volumio1 volumio[14615]: info: MyVolumio login type: Token
Jul 18 14:58:41 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:41 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79.
Jul 18 14:58:41 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:41 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:41 volumio1 go-librespot[15980]: Librespot-go daemon starting...
Jul 18 14:58:41 volumio1 go-librespot[15980]: time="2024-07-18T14:58:41+08:00" level=info msg="generated new device id: 6a1bc5a696ec7a5f4228f0576a31c66c719dc508"
Jul 18 14:58:41 volumio1 go-librespot[15980]: time="2024-07-18T14:58:41+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:42 volumio1 go-librespot[15980]: time="2024-07-18T14:58:42+08:00" level=debug msg="obtained new client token: AAD7eHDiNwRbSVf5u7crUncngXd0pTwrbdKomVZ+sFlm0E7UB69goYwPZ1Bs8qgTqDllavNV7O0CXX98c44Jk9QMMOTxpHG+axGWg2LkEJngTUxpsVeKSAwG/UCRP+MB9a6giuvioOk3NJssMi/lc+wlqOFXbwV5omxgEhL/Vm3XbUXvrAq8uy9yJqf40PvZCIi32MLHR+e3/UrGYvBGsN70rEr9Fohg/Mi7m5gJofh0w65duWISuo4ijvs="
Jul 18 14:58:42 volumio1 go-librespot[15980]: time="2024-07-18T14:58:42+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:58:42 volumio1 go-librespot[15980]: time="2024-07-18T14:58:42+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:42 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:42 volumio1 go-librespot[15980]: time="2024-07-18T14:58:42+08:00" level=debug msg="new websocket client"
Jul 18 14:58:42 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:58:42 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:42 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:42 volumio1 go-librespot[15980]: time="2024-07-18T14:58:42+08:00" level=debug msg="completed challenge"
Jul 18 14:58:43 volumio1 go-librespot[15980]: time="2024-07-18T14:58:43+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:43 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:43 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:43 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:58:43 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:58:43 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Jul 18 14:58:43 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Jul 18 14:58:43 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Jul 18 14:58:43 volumio1 volumio[14615]: info: Received Get System Version
Jul 18 14:58:43 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Jul 18 14:58:44 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:44 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:45 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:58:45 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:45 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:58:45 volumio1 volumio[14615]: (node:14615) 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: 38)
Jul 18 14:58:45 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:58:45 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:45 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:45 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Jul 18 14:58:46 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:46 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:46 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:46 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80.
Jul 18 14:58:46 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:46 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:46 volumio1 go-librespot[15988]: Librespot-go daemon starting...
Jul 18 14:58:46 volumio1 go-librespot[15988]: time="2024-07-18T14:58:46+08:00" level=info msg="generated new device id: 2076d4d8fb2a1b915f8ffd9dbafab59a952648cf"
Jul 18 14:58:46 volumio1 go-librespot[15988]: time="2024-07-18T14:58:46+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:46 volumio1 go-librespot[15988]: time="2024-07-18T14:58:46+08:00" level=debug msg="obtained new client token: AABMU+ACfEYKBrpVIkCxMl3swJW/SknD9pgxl37E0veOcAj6VDLHnyG1H3JQENMgg9MF4iPhHKY6YGN5/fW7MotYRb42oBADN/vlr5FGqW2JO7PJjZuSKZOYIv4E9LPBwM2ylcmCA0G6/iS/OHcW0y8jx2iZBf2vjFTuc2YHiKQAgl4DLi+sf5v9u48HD9OAJ9JJGmqvJH+zABjlma1QzkbUoiSdn8uIJlL7G8wqnJ03IZn0SuNDlDiVDP3pbg=="
Jul 18 14:58:46 volumio1 go-librespot[15988]: time="2024-07-18T14:58:46+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:46 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:46 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:46 volumio1 go-librespot[15988]: time="2024-07-18T14:58:46+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:47 volumio1 go-librespot[15988]: time="2024-07-18T14:58:47+08:00" level=debug msg="completed challenge"
Jul 18 14:58:47 volumio1 go-librespot[15988]: time="2024-07-18T14:58:47+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:47 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:47 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:48 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:48 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:49 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:49 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:50 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:50 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 81.
Jul 18 14:58:50 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:50 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:50 volumio1 go-librespot[15997]: Librespot-go daemon starting...
Jul 18 14:58:50 volumio1 go-librespot[15997]: time="2024-07-18T14:58:50+08:00" level=info msg="generated new device id: abd0c9e646c7bf8ee8d7364d70baa034963d2dda"
Jul 18 14:58:50 volumio1 go-librespot[15997]: time="2024-07-18T14:58:50+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:50 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:50 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:51 volumio1 go-librespot[15997]: time="2024-07-18T14:58:51+08:00" level=debug msg="obtained new client token: AADoqsvzyffth5g9F1UUH+MsDD2KoCqOkDRlmVyLMPVuOXkMkH3gxLeo7xPAnh2pYlvWTgDIh19J0mjjw2ZPsiXK2zQadWbKR7V4lVOWgX0apwjTrX3CNGKHVv/C2qjncuv8154BmrUJHJULUUBhvRI36i7lZ60LXNKDEZHNxwaTA4K2BJ1SnqrgmfQrCkfc0UP0vVLzoNQYAPW6tDLnrMkN+XZsyUdF/hlkcoBk1Zj+GmeJLBZszFwnGEM="
Jul 18 14:58:51 volumio1 go-librespot[15997]: time="2024-07-18T14:58:51+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:51 volumio1 go-librespot[15997]: time="2024-07-18T14:58:51+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:51 volumio1 go-librespot[15997]: time="2024-07-18T14:58:51+08:00" level=debug msg="completed challenge"
Jul 18 14:58:52 volumio1 go-librespot[15997]: time="2024-07-18T14:58:52+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:52 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:52 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:52 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:52 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:52 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:52 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:54 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:54 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:54 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume95
Jul 18 14:58:54 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:54 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:54 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:54 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 95
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 100
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 95
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:55 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 95
Jul 18 14:58:55 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:55 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:55 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:58:55 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 82.
Jul 18 14:58:55 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:58:55 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:58:55 volumio1 go-librespot[16006]: Librespot-go daemon starting...
Jul 18 14:58:55 volumio1 go-librespot[16006]: time="2024-07-18T14:58:55+08:00" level=info msg="generated new device id: d907586d874dfcfca731dad014914abda8120196"
Jul 18 14:58:55 volumio1 go-librespot[16006]: time="2024-07-18T14:58:55+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:58:55 volumio1 volumio[14615]: info: VolumeController::SetAlsaVolume56
Jul 18 14:58:55 volumio1 volumio[14615]: info: CoreStateMachine::pushState
Jul 18 14:58:55 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:55 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jul 18 14:58:55 volumio1 volumio[14615]: info: CoreCommandRouter::volumioPushState
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: SPOTIFY VOLUME 95
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: VOLUMIO VOLUME 56
Jul 18 14:58:55 volumio1 volumio[14615]: SPOTIFY: DELTA VOLUME ENOUGH: true
Jul 18 14:58:55 volumio1 volumio[14615]: info: Setting Spotify Volume from Volumio: 56
Jul 18 14:58:55 volumio1 go-librespot[16006]: time="2024-07-18T14:58:55+08:00" level=debug msg="obtained new client token: AACHy5/VzqnVk0sX0/sVUO8ObN3+pkaInpQmhBKsqZOcyymR51NA4ofH2XYsQKkuajDtCqjGy0xkLZXkO5lAy1hxWohDoN/mgshobqxsf56GM9a1g453mgCDgM/WhQNO8vWjiNx+wPt4uD4kAPw5C5HOcFnz6TAZSWr5ObJ0BwNGUbA5jOyj4r8O9pN3Pen+ajdAGl/j16jlF+07nG71A/2986mDkUS2eU34Mpm3ETvni1FCzdzbe+zBHxbDYA=="
Jul 18 14:58:55 volumio1 go-librespot[16006]: time="2024-07-18T14:58:55+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:58:56 volumio1 go-librespot[16006]: time="2024-07-18T14:58:56+08:00" level=debug msg="completed keyexchange"
Jul 18 14:58:56 volumio1 go-librespot[16006]: time="2024-07-18T14:58:56+08:00" level=debug msg="completed challenge"
Jul 18 14:58:56 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:56 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:56 volumio1 go-librespot[16006]: time="2024-07-18T14:58:56+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:58:56 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:58:56 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:58:57 volumio1 volumio[14615]: SPOTIFY: SETTING SPOTIFY VOLUME 56
Jul 18 14:58:57 volumio1 volumio[14615]: info: Sending Spotify command with payload to local API: /player/volume
Jul 18 14:58:57 volumio1 volumio[14615]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:58 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:58:58 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:58:58 volumio1 volumio[14615]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object]
Jul 18 14:58:58 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset
Jul 18 14:58:58 volumio1 volumio[14615]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false
Jul 18 14:58:58 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:58:58 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:58:58 volumio1 volumio[14615]: info: FusionDsp - If filter freq >samplerate/2 then disable it
Jul 18 14:58:58 volumio1 volumio[14615]: info: FusionDsp - Effects disabled
Jul 18 14:58:58 volumio1 volumio[14615]: info: FusionDsp - {"Reload":{"result":"Ok"}}
Jul 18 14:58:58 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:58:58 volumio1 volumio[14615]: info: CoreCommandRouter::Close All Modals sent
Jul 18 14:58:59 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:59:00 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:00 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 83.
Jul 18 14:59:00 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:00 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:00 volumio1 go-librespot[16016]: Librespot-go daemon starting...
Jul 18 14:59:00 volumio1 go-librespot[16016]: time="2024-07-18T14:59:00+08:00" level=info msg="generated new device id: 191b70faa62bb0bc868f0b0a1aad0c30c8fe998e"
Jul 18 14:59:00 volumio1 go-librespot[16016]: time="2024-07-18T14:59:00+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:00 volumio1 go-librespot[16016]: time="2024-07-18T14:59:00+08:00" level=debug msg="obtained new client token: AAAj5RyE5y/NxZ3WsyQLF1PWDSBO3WSmuizRBrTkz9qb6zxxwWB1hyTWiNYdUROc7GPXlsqqmbBOxMOgVOP5tKcJspovF7LsLmMH1RMXcJS07Ob0Ypo7wTKhpdEFgJfqsh2sL43kD4Ic0ejXFR2F2/Kv97AKqRlyuiYhnayIBCKiuy7/3BwB3RWKInBWJdA6DpFxDCh7RyPetOz+8dWEeO418OdA6oOPRG3izkuV9TfY8v8bQgibUwns+rwwbA=="
Jul 18 14:59:00 volumio1 go-librespot[16016]: time="2024-07-18T14:59:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:00 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:00 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:00 volumio1 go-librespot[16016]: time="2024-07-18T14:59:00+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:01 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:01 volumio1 go-librespot[16016]: time="2024-07-18T14:59:01+08:00" level=debug msg="new websocket client"
Jul 18 14:59:01 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:59:01 volumio1 go-librespot[16016]: time="2024-07-18T14:59:01+08:00" level=debug msg="completed challenge"
Jul 18 14:59:01 volumio1 go-librespot[16016]: time="2024-07-18T14:59:01+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:01 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:01 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:01 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:59:02 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:02 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:04 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:59:04 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:04 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:59:04 volumio1 volumio[14615]: (node:14615) 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: 39)
Jul 18 14:59:04 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:59:04 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:04 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:04 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:59:04 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:04 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:04 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:04 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 84.
Jul 18 14:59:04 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:04 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:04 volumio1 go-librespot[16024]: Librespot-go daemon starting...
Jul 18 14:59:04 volumio1 go-librespot[16024]: time="2024-07-18T14:59:04+08:00" level=info msg="generated new device id: 5a38d5599a194b57996efd7dbc114643e70a2457"
Jul 18 14:59:04 volumio1 go-librespot[16024]: time="2024-07-18T14:59:04+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:04 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:04 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:05 volumio1 go-librespot[16024]: time="2024-07-18T14:59:05+08:00" level=debug msg="obtained new client token: AAADGFitXoJTFoLRXrVlKhyoYDjhvGPBzxVTJA4KJ1gIAcdFmMUwOMYIC+fvTq3JZCUNJDm93e6jKmECmz8PUQl+yKxBDs90Tr+6ZnsVp4Xz/95jL27mEL2bRLqvUPDhRCkDF86ej4qgQiuhQ82wHasaPSGZqvBQWvmx3Tnk2cw79hPBgJwmJzCCT5G5zduz++mBEPz4s8eXheYZ7PczsWxVNsmx2pcHpNr7M2livkLAv0iXRZs24Ba/RaM="
Jul 18 14:59:05 volumio1 go-librespot[16024]: time="2024-07-18T14:59:05+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:05 volumio1 go-librespot[16024]: time="2024-07-18T14:59:05+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:05 volumio1 go-librespot[16024]: time="2024-07-18T14:59:05+08:00" level=debug msg="completed challenge"
Jul 18 14:59:06 volumio1 go-librespot[16024]: time="2024-07-18T14:59:06+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:06 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:06 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:06 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:06 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:07 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:07 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:08 volumio1 volumio[14615]: info: CALLMETHOD: audio_interface fusiondsp choosedsp [object Object]
Jul 18 14:59:08 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , choosedsp
Jul 18 14:59:08 volumio1 volumio[14615]: info: FusionDsp - If filter freq >samplerate/2 then disable it
Jul 18 14:59:08 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:59:08 volumio1 volumio[14615]: info: CoreCommandRouter::Close All Modals sent
Jul 18 14:59:09 volumio1 volumio[14615]: info: FusionDsp - {"Reload":{"result":"Ok"}}
Jul 18 14:59:09 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:09 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:09 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:09 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 85.
Jul 18 14:59:09 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:09 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:09 volumio1 go-librespot[16034]: Librespot-go daemon starting...
Jul 18 14:59:09 volumio1 go-librespot[16034]: time="2024-07-18T14:59:09+08:00" level=info msg="generated new device id: 1d86e0d0f858c72ddff3ae3441112520255f0a2f"
Jul 18 14:59:09 volumio1 go-librespot[16034]: time="2024-07-18T14:59:09+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:09 volumio1 go-librespot[16034]: time="2024-07-18T14:59:09+08:00" level=debug msg="obtained new client token: AABE4dobYeYmH3zutv0WCo653YZlJbHqwrIHJuxbOCeWBmHB/tbHfYnsT0bDu/JuSF20h8PpJVkzE4adePFfM7Ng34u4fy3RnjfKxH3fT3WPyyk3shnP9isVRt0Wd+B0wN5ySEGAn0Ir19fqpKLyim1Y2020YaaSPTl+XaHD0ou/vW4EHlJzBbFVUuAvHrZ4ZS0cz7s4+qjg9+HzjOHjvi6+9C1IUW47cT5jP+4r8ImGpDl2cyQUv6qDUXRUoQ=="
Jul 18 14:59:09 volumio1 go-librespot[16034]: time="2024-07-18T14:59:09+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:10 volumio1 go-librespot[16034]: time="2024-07-18T14:59:10+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:10 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:10 volumio1 go-librespot[16034]: time="2024-07-18T14:59:10+08:00" level=debug msg="new websocket client"
Jul 18 14:59:10 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:59:10 volumio1 go-librespot[16034]: time="2024-07-18T14:59:10+08:00" level=debug msg="completed challenge"
Jul 18 14:59:10 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:10 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:10 volumio1 go-librespot[16034]: time="2024-07-18T14:59:10+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:10 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:10 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:10 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:59:11 volumio1 volumio[14615]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred.
Jul 18 14:59:11 volumio1 volumio[14615]: info: Retrying Login Due to Network Error
Jul 18 14:59:12 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:12 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:13 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:59:13 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:13 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:59:13 volumio1 volumio[14615]: (node:14615) 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: 40)
Jul 18 14:59:13 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:59:13 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:13 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:13 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:59:13 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:13 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:13 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:13 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 86.
Jul 18 14:59:13 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:13 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:13 volumio1 go-librespot[16042]: Librespot-go daemon starting...
Jul 18 14:59:13 volumio1 go-librespot[16042]: time="2024-07-18T14:59:13+08:00" level=info msg="generated new device id: 92d42e2029b86a651830b7e9420c1afe951bcbc9"
Jul 18 14:59:13 volumio1 go-librespot[16042]: time="2024-07-18T14:59:13+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:14 volumio1 go-librespot[16042]: time="2024-07-18T14:59:14+08:00" level=debug msg="obtained new client token: AAC/80er7vJ8CK0rDKdikBNCwKWaevRykJ8gux2WDSW6ZgudBhYBDY4pvco7agnsY4nEQBvOMVnq5jhB4RdAWO76TXoHaEz2RxAoDVG2M1VONIevZpTUBZCgBZ7JqEcVpkQ3eUGN9WIfdqDJY7/RXTOlcy0BAKvb5OzK+p3vNAIvWu3asBl0JoDwKdyUGgjkP8Z/SPsxCAH3HOSof58BwyQ2qyeYo59N64BDd5mrAgWRlVnLBtxgCEz/SyXpTw=="
Jul 18 14:59:14 volumio1 go-librespot[16042]: time="2024-07-18T14:59:14+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:59:14 volumio1 go-librespot[16042]: time="2024-07-18T14:59:14+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:14 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:14 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:15 volumio1 go-librespot[16042]: time="2024-07-18T14:59:15+08:00" level=debug msg="completed challenge"
Jul 18 14:59:15 volumio1 go-librespot[16042]: time="2024-07-18T14:59:15+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:15 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:15 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:16 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:16 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:16 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:16 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:18 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:18 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 87.
Jul 18 14:59:18 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:18 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:18 volumio1 go-librespot[16050]: Librespot-go daemon starting...
Jul 18 14:59:18 volumio1 go-librespot[16050]: time="2024-07-18T14:59:18+08:00" level=info msg="generated new device id: 117769752d8735526f2380e9308738fe41b85745"
Jul 18 14:59:18 volumio1 go-librespot[16050]: time="2024-07-18T14:59:18+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:18 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:18 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:18 volumio1 go-librespot[16050]: time="2024-07-18T14:59:18+08:00" level=debug msg="obtained new client token: AAAiav7NUyk4lJvlA1P06lbJS/xl8K8TlFpUyDAD3fhhNOy7CX4mergVf7jKlRBvD/yOgREnWZWtqAq7Kms5cxb7fLcz0wd9VQh1wDZQXLsx7ydEJySOwzsJDIlMKSplg/VpMP5rFN/+cvWKTC/wE/TfZVapqgQZUlaQNQeC7HkXqT+x45D0CD1AYzFmJ023dhb38ymKxqpCO+4Nc0V46jS/08EfUquiOxEApnm64DcUyIKy9pO3pg8pZs5L1w=="
Jul 18 14:59:19 volumio1 go-librespot[16050]: time="2024-07-18T14:59:19+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:19 volumio1 go-librespot[16050]: time="2024-07-18T14:59:19+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:19 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:19 volumio1 go-librespot[16050]: time="2024-07-18T14:59:19+08:00" level=debug msg="new websocket client"
Jul 18 14:59:19 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:59:20 volumio1 go-librespot[16050]: time="2024-07-18T14:59:20+08:00" level=debug msg="completed challenge"
Jul 18 14:59:20 volumio1 go-librespot[16050]: time="2024-07-18T14:59:20+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:20 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:20 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:20 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:59:20 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:20 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:21 volumio1 volumio[14615]: info: MyVolumio login type: Token
Jul 18 14:59:22 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:22 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:22 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:59:22 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:22 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:59:22 volumio1 volumio[14615]: (node:14615) 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: 41)
Jul 18 14:59:22 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:59:23 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:23 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:23 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:59:23 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:23 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:23 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:23 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88.
Jul 18 14:59:23 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:23 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:23 volumio1 go-librespot[16099]: Librespot-go daemon starting...
Jul 18 14:59:23 volumio1 go-librespot[16099]: time="2024-07-18T14:59:23+08:00" level=info msg="generated new device id: 22e41004a90670f1123027c2c6afab8ae4a39fcf"
Jul 18 14:59:23 volumio1 go-librespot[16099]: time="2024-07-18T14:59:23+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:23 volumio1 go-librespot[16099]: time="2024-07-18T14:59:23+08:00" level=debug msg="obtained new client token: AACqO08HtmNmAZDHfGrihHcG8dHUh6bcMf5PGMZGlcZXQOuVOrEmTHnciKa8L4SV4syV/oJSjz7flZW135gq5FI/0VNP4U1YiMkCFY9I10UR5+BQuUxsmDNmV/ie8FBxXZRVqFepw0rgAmSyVLOsurd/ChXfIk8gedrADeIurtitaxIDv3HDHXlrMtWuYNjzuUV219ur7chxotzSVJFLjjHeS6q8SHiku+/GllncVb2EXQQrNCkW78/EjjVmAA=="
Jul 18 14:59:24 volumio1 go-librespot[16099]: time="2024-07-18T14:59:24+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:24 volumio1 go-librespot[16099]: time="2024-07-18T14:59:24+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:24 volumio1 go-librespot[16099]: time="2024-07-18T14:59:24+08:00" level=debug msg="completed challenge"
Jul 18 14:59:24 volumio1 go-librespot[16099]: time="2024-07-18T14:59:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:24 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:24 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:24 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:24 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:26 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:26 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:26 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:26 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:27 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:27 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89.
Jul 18 14:59:27 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:27 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:27 volumio1 go-librespot[16108]: Librespot-go daemon starting...
Jul 18 14:59:27 volumio1 go-librespot[16108]: time="2024-07-18T14:59:27+08:00" level=info msg="generated new device id: a909e63b4e9436077820b7bef0fe4187ad564bc0"
Jul 18 14:59:27 volumio1 go-librespot[16108]: time="2024-07-18T14:59:27+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:28 volumio1 go-librespot[16108]: time="2024-07-18T14:59:28+08:00" level=debug msg="obtained new client token: AAAyMBGuigFGtQXM1n45Fexhm/zSEvF1+BXy4/Uus2eMm3x3VKG1lGRddvt1X0hkP14ajHp0XG3QJwQGm4Kl0CH98qWOXLmhqwmsjadJGfkE5BiXwZbeK+8N6g7Nw+DHuAGsy3pAvrPNxu0fM6W6x2Hg7tOijaRNt8X+Snna8VUksxCFhP9SD3WQkJjguHUpdkEP7w4QknuiHr7bs9PP5DZBuZJQNYy9P0e94fe6849ICHptzvjXvMGmpzz7mA=="
Jul 18 14:59:28 volumio1 go-librespot[16108]: time="2024-07-18T14:59:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:59:28 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:28 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:28 volumio1 go-librespot[16108]: time="2024-07-18T14:59:28+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:29 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:29 volumio1 go-librespot[16108]: time="2024-07-18T14:59:29+08:00" level=debug msg="new websocket client"
Jul 18 14:59:29 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:59:29 volumio1 go-librespot[16108]: time="2024-07-18T14:59:29+08:00" level=debug msg="completed challenge"
Jul 18 14:59:29 volumio1 go-librespot[16108]: time="2024-07-18T14:59:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:29 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:29 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:29 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:59:30 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:30 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:32 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:59:32 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:32 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:59:32 volumio1 volumio[14615]: (node:14615) 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: 42)
Jul 18 14:59:32 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:59:32 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:32 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:32 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:59:32 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:32 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:32 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:32 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:32 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:32 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90.
Jul 18 14:59:32 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:32 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:32 volumio1 go-librespot[16116]: Librespot-go daemon starting...
Jul 18 14:59:32 volumio1 go-librespot[16116]: time="2024-07-18T14:59:32+08:00" level=info msg="generated new device id: 1f12972a251d7a4e19e54a57af9e6eab366ecf19"
Jul 18 14:59:32 volumio1 go-librespot[16116]: time="2024-07-18T14:59:32+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:33 volumio1 go-librespot[16116]: time="2024-07-18T14:59:33+08:00" level=debug msg="obtained new client token: AACa6oPccCJXby6l43/iQE12aWgaOMJf0pwBIhSmVpOkYrHtWwcrP9YDVNPkkUPsDOsJbjhEJzATt/mfyl763oxqPVLl/Aco6BOtSRtGSlrheFWD6cPV0eAfNcemtoEyvYfORnqJ4SVWMEj4k+c+iUURR9hCEYnAsXdNSy+/HRLEWNhkckoCYckr2pBQIOUnCaWOF1ZwefK2vyxXIn1/I/jSBfDGuM5kjyWE4gXcaOHVx9GVzAgv4ZCIge0ZVA=="
Jul 18 14:59:33 volumio1 go-librespot[16116]: time="2024-07-18T14:59:33+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:59:33 volumio1 go-librespot[16116]: time="2024-07-18T14:59:33+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:34 volumio1 go-librespot[16116]: time="2024-07-18T14:59:34+08:00" level=debug msg="completed challenge"
Jul 18 14:59:34 volumio1 go-librespot[16116]: time="2024-07-18T14:59:34+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:34 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:34 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:34 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:34 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:35 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:35 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:35 volumio1 volumio[14615]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object]
Jul 18 14:59:35 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset
Jul 18 14:59:35 volumio1 volumio[14615]: info: FusionDsp - geq15 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
Jul 18 14:59:35 volumio1 volumio[14615]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false
Jul 18 14:59:36 volumio1 volumio[14615]: info: FusionDsp - If filter freq >samplerate/2 then disable it
Jul 18 14:59:36 volumio1 volumio[14615]: info: FusionDsp - {"Reload":{"result":"Ok"}}
Jul 18 14:59:36 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:59:36 volumio1 volumio[14615]: info: CoreCommandRouter::Close All Modals sent
Jul 18 14:59:37 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:59:37 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:37 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:37 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:37 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91.
Jul 18 14:59:37 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:37 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:37 volumio1 go-librespot[16125]: Librespot-go daemon starting...
Jul 18 14:59:37 volumio1 go-librespot[16125]: time="2024-07-18T14:59:37+08:00" level=info msg="generated new device id: c48895def3deb12e6d6fd38cf1f3a70c6fa8e22f"
Jul 18 14:59:37 volumio1 go-librespot[16125]: time="2024-07-18T14:59:37+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:38 volumio1 go-librespot[16125]: time="2024-07-18T14:59:38+08:00" level=debug msg="obtained new client token: AAAt54scTFrIGWceW4WZCQonc1IRashENBwtliIQ9VV04PFpp/SwkH0bLk1N0J3GrZ8pIdTDz6RVbcECEuSjsxOHaq+kskrT0qdP4q/FZ2jOpzE7vZhaUXaLahAO3vPleghW07Bznt6BCkjTNSSvpc8z/wTMSupYLGkNgDixkpbi+pYL+0C6R/QnP+mi0cIe+BCCFXCRNqSQJMVI37afZTOml7g/8hgz0ETHbovql5NkCfpX/sdaxdzmSGn3sg=="
Jul 18 14:59:38 volumio1 go-librespot[16125]: time="2024-07-18T14:59:38+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Jul 18 14:59:38 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:38 volumio1 go-librespot[16125]: time="2024-07-18T14:59:38+08:00" level=debug msg="new websocket client"
Jul 18 14:59:38 volumio1 volumio[14615]: info: Connection to go-librespot Websocket established
Jul 18 14:59:38 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:38 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:38 volumio1 go-librespot[16125]: time="2024-07-18T14:59:38+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:39 volumio1 go-librespot[16125]: time="2024-07-18T14:59:39+08:00" level=debug msg="completed challenge"
Jul 18 14:59:39 volumio1 go-librespot[16125]: time="2024-07-18T14:59:39+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:39 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:39 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:39 volumio1 volumio[14615]: info: Connection to go-librespot Websocket closed
Jul 18 14:59:40 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:40 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:41 volumio1 volumio[14615]: info: Getting Spotify volume
Jul 18 14:59:41 volumio1 volumio[14615]: (node:14615) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:41 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16)
Jul 18 14:59:41 volumio1 volumio[14615]: (node:14615) 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: 43)
Jul 18 14:59:41 volumio1 volumio[14615]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Jul 18 14:59:41 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:41 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:41 volumio1 volumio[14615]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56
Jul 18 14:59:42 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:42 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:42 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:42 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:42 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:42 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92.
Jul 18 14:59:42 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:42 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:42 volumio1 go-librespot[16133]: Librespot-go daemon starting...
Jul 18 14:59:42 volumio1 go-librespot[16133]: time="2024-07-18T14:59:42+08:00" level=info msg="generated new device id: 01d4bc6569215b9c7f5832e0997dfc6f33de6ed0"
Jul 18 14:59:42 volumio1 go-librespot[16133]: time="2024-07-18T14:59:42+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
Jul 18 14:59:43 volumio1 go-librespot[16133]: time="2024-07-18T14:59:43+08:00" level=debug msg="obtained new client token: AAB17Mo6R/gQw6uaR8QvZ1uuIyIVOSKnvkwKiqMGyvUTQ7+rm2xJGELwhwcv9InWqErYNa3uSeOGw8cIeMEeiOYsC+M2s1jFWmC/+3ZzKvyy1dmiwoUx2f/kWCsUa76y3mVWwyRDi+tE9pW3C3lc1MCVUMpcwM/O3Q8QzY6zru3kbhkwN5sbT+69Cwn/0jXEI8dLvachkhc3RHdzsIGj6FuNxrBKDACzRDDr3a8f/PkVnFtIQuDv9mA4J8ZRWw=="
Jul 18 14:59:43 volumio1 go-librespot[16133]: time="2024-07-18T14:59:43+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Jul 18 14:59:44 volumio1 go-librespot[16133]: time="2024-07-18T14:59:44+08:00" level=debug msg="completed keyexchange"
Jul 18 14:59:44 volumio1 go-librespot[16133]: time="2024-07-18T14:59:44+08:00" level=debug msg="completed challenge"
Jul 18 14:59:44 volumio1 go-librespot[16133]: time="2024-07-18T14:59:44+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Jul 18 14:59:44 volumio1 volumio[14615]: info: CoreCommandRouter::volumioGetState
Jul 18 14:59:44 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Jul 18 14:59:44 volumio1 volumio[14615]: info: CorePlayQueue::getTrack 5
Jul 18 14:59:44 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Jul 18 14:59:45 volumio1 volumio[14615]: info: Initializing connection to go-librespot Websocket
Jul 18 14:59:45 volumio1 volumio[14615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Jul 18 14:59:46 volumio1 volumio[14615]: info: CALLMETHOD: audio_interface fusiondsp choosedsp [object Object]
Jul 18 14:59:46 volumio1 volumio[14615]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , choosedsp
Jul 18 14:59:46 volumio1 volumio[14615]: info: FusionDsp - If filter freq >samplerate/2 then disable it
Jul 18 14:59:46 volumio1 volumio[14615]: info: CoreCommandRouter::getUIConfigOnPlugin
Jul 18 14:59:46 volumio1 volumio[14615]: info: CoreCommandRouter::Close All Modals sent
Jul 18 14:59:46 volumio1 volumio[14615]: info: FusionDsp - {"Reload":{"result":"Ok"}}
Jul 18 14:59:46 volumio1 volumio[14615]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Jul 18 14:59:46 volumio1 volumio[14615]: Error: connect ETIMEDOUT 67.15.129.210:443
Jul 18 14:59:46 volumio1 volumio[14615]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) {
Jul 18 14:59:46 volumio1 volumio[14615]: errno: -110,
Jul 18 14:59:46 volumio1 volumio[14615]: code: 'ETIMEDOUT',
Jul 18 14:59:46 volumio1 volumio[14615]: syscall: 'connect',
Jul 18 14:59:46 volumio1 volumio[14615]: address: '67.15.129.210',
Jul 18 14:59:46 volumio1 volumio[14615]: port: 443
Jul 18 14:59:46 volumio1 volumio[14615]: }
Jul 18 14:59:46 volumio1 volumio[14615]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Jul 18 14:59:47 volumio1 sudo[16154]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-18 14:58
Jul 18 14:59:47 volumio1 sudo[16154]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 18 14:59:47 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Jul 18 14:59:47 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93.
Jul 18 14:59:47 volumio1 systemd[1]: Stopped go-librespot Daemon.
Jul 18 14:59:47 volumio1 systemd[1]: Started go-librespot Daemon.
Jul 18 14:59:47 volumio1 go-librespot[16156]: Librespot-go daemon starting...
Jul 18 14:59:48 volumio1 go-librespot[16156]: time="2024-07-18T14:59:48+08:00" level=info msg="generated new device id: 815d2af52d3686a18db233693dd4ee2ef0d71e7c"
Jul 18 14:59:48 volumio1 go-librespot[16156]: time="2024-07-18T14:59:48+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu"
PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
VOLUMIO_BUILD_VERSION="6e682b9410d28f3874f90b2d7789db824a859264"
VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6"
VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a"
VOLUMIO_BE_VERSION="7c81f20187867c3bd55475ead0f12800fe93082c"
VOLUMIO_ARCH="armv7"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Sat 08 Jun 2024 10:32:20 PM CEST"
VOLUMIO_VERSION="3.703"
VOLUMIO_HARDWARE="orangepipc"
VOLUMIO_DEVICENAME="Orange Pi PC"
VOLUMIO_HASH="85fabbf1ff267d6584c35638894541bf"