-- Logs begin at Sun 2025-06-01 09:44:05 CEST, end at Sun 2025-06-01 11:58:17 CEST. -- Jun 01 11:57:01 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:57:01 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:01 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:57:01 theoffice volumio[953]: (node:953) 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: 91677) Jun 01 11:57:01 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:57:01 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:01 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:01 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:57:01 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:01 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:01 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:01 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274924. Jun 01 11:57:01 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:02 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:02 theoffice go-librespot[26203]: Librespot-go daemon starting... Jun 01 11:57:02 theoffice go-librespot[26203]: time="2025-06-01T11:57:02+02:00" level=info msg="generated new device id: 8539cf3bbead17cb31f15fb80cc92d27a5893c69" Jun 01 11:57:02 theoffice go-librespot[26203]: time="2025-06-01T11:57:02+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:02 theoffice go-librespot[26203]: time="2025-06-01T11:57:02+02:00" level=debug msg="obtained new client token: AADboGw4d8I/yMq73LtRq9p5eZ560nvU/l1VjBuxaxfsg+IO1PxcnyZ7DKoR7kOC9BHlCVRPIuBBRgxAEBwoBpEtMxS625K3b0nlGtm//vKWN4yjiAgEtSvwFPyfitRjXeTdKh2wQoUWp91lNvXMTdrTsUxJDzneUTUkuZq75KDsm9gApi8di1v4CavOGaSXGOI3nXiUhyROD5Z4MgHEQf1qlJauENNRexo4Q8F+wNvoZoJwbq4qnVDih+0fbdk=" Jun 01 11:57:02 theoffice go-librespot[26203]: time="2025-06-01T11:57:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:02 theoffice go-librespot[26203]: time="2025-06-01T11:57:02+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:03 theoffice go-librespot[26203]: time="2025-06-01T11:57:03+02:00" level=debug msg="completed challenge" Jun 01 11:57:03 theoffice go-librespot[26203]: time="2025-06-01T11:57:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:03 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:03 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:04 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:04 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:04 theoffice volumio[953]: info: Listing playlists Jun 01 11:57:04 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:04 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:06 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:06 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274925. Jun 01 11:57:06 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:06 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:06 theoffice go-librespot[26223]: Librespot-go daemon starting... Jun 01 11:57:06 theoffice go-librespot[26223]: time="2025-06-01T11:57:06+02:00" level=info msg="generated new device id: ba1685c6101d33c941bc83eb3dd4aafaf20de80a" Jun 01 11:57:06 theoffice go-librespot[26223]: time="2025-06-01T11:57:06+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:06 theoffice go-librespot[26223]: time="2025-06-01T11:57:06+02:00" level=debug msg="obtained new client token: AAB2GUErgVAzcQSnqapeYWdHKzqjxMJFNEATh6HseoqGc5GtF2F2QFx41MsvfhWCifdzAUfUaBMWFJJDG9IX5S+16J7ThVtC/cF6xPOzF2nBx0XazWasdXDvdQs80StkK313fhidUHKHWRS1DQqxK+P1fI2DvkOwFc5fNl5Q1BteJl4YqQYMruQ6XLWhrE5XzWOERAoqjVwuRwEmRdpvfwsrCybMp4B+BeyNMOMzfzOkg3w8Uqm7wMWQPLLH7/k=" Jun 01 11:57:06 theoffice go-librespot[26223]: time="2025-06-01T11:57:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:06 theoffice go-librespot[26223]: time="2025-06-01T11:57:06+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:07 theoffice go-librespot[26223]: time="2025-06-01T11:57:07+02:00" level=debug msg="completed challenge" Jun 01 11:57:07 theoffice go-librespot[26223]: time="2025-06-01T11:57:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:07 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:07 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:07 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:07 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:10 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:10 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274926. Jun 01 11:57:10 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:10 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:10 theoffice go-librespot[26246]: Librespot-go daemon starting... Jun 01 11:57:10 theoffice go-librespot[26246]: time="2025-06-01T11:57:10+02:00" level=info msg="generated new device id: 2000a4ec58e9481882621cce83eb48f32e1fe015" Jun 01 11:57:10 theoffice go-librespot[26246]: time="2025-06-01T11:57:10+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:10 theoffice go-librespot[26246]: time="2025-06-01T11:57:10+02:00" level=debug msg="obtained new client token: AAAb0osqf11UFT6jCy20ZObBIKigDF7aeGeEtsyefj3eMoBqIZvGYwGwPZw+knnooJ/uk0gGSjbkWuYLJOmWSY97/LnuD7f2SB8q+d7TRTouliTjIxKSNzgLu8GHT0NV+q0FJJSryJFVGi83c7hYVvUd5Q8WEqIKCzxQh5VhGqd55hfHQZfJRSrG4XZ/klQHqcUbt30Uu8so97SS3Z+wx2WCnkCoQZln75HBRBzjBoS3kcoJdWukYzUvUbxzed8=" Jun 01 11:57:10 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:10 theoffice go-librespot[26246]: time="2025-06-01T11:57:10+02:00" level=debug msg="new websocket client" Jun 01 11:57:10 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:57:10 theoffice go-librespot[26246]: time="2025-06-01T11:57:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:11 theoffice go-librespot[26246]: time="2025-06-01T11:57:11+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:11 theoffice go-librespot[26246]: time="2025-06-01T11:57:11+02:00" level=debug msg="completed challenge" Jun 01 11:57:11 theoffice go-librespot[26246]: time="2025-06-01T11:57:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:11 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:57:11 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:11 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:13 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:57:13 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:13 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:57:13 theoffice volumio[953]: (node:953) 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: 91678) Jun 01 11:57:13 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:57:13 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:13 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:13 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:57:14 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:14 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:14 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:14 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:14 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:14 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274927. Jun 01 11:57:14 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:14 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:14 theoffice go-librespot[26266]: Librespot-go daemon starting... Jun 01 11:57:14 theoffice go-librespot[26266]: time="2025-06-01T11:57:14+02:00" level=info msg="generated new device id: 6d464eaaa6365ce50e10715fe13d7fb66cf15e61" Jun 01 11:57:14 theoffice go-librespot[26266]: time="2025-06-01T11:57:14+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:15 theoffice go-librespot[26266]: time="2025-06-01T11:57:15+02:00" level=debug msg="obtained new client token: AACWhXh6uCzk8ugVbJcIN6PU+UArSjkqOyXQ/pSKzJIQ6eC25kH0yAMG7/WwnsAzkFfEU+/3zvr2u7hmfgtWmTKGw3zcgkcrAl2jD6zNEMbeyUhC8ISuHbQm0MNkXyzdojyZKlmnqkAEV7IYFMieNzQL5NFebmYaL1CJL/HFVRolhceJBhR0Td+YvMjEtv/XQiaB5wEjGPRQp9FIyJIXA8DdqDk/hKx5omrVGVBi5xsD6te8Nrbl7HUOUF/i" Jun 01 11:57:15 theoffice go-librespot[26266]: time="2025-06-01T11:57:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:15 theoffice go-librespot[26266]: time="2025-06-01T11:57:15+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:15 theoffice go-librespot[26266]: time="2025-06-01T11:57:15+02:00" level=debug msg="completed challenge" Jun 01 11:57:15 theoffice go-librespot[26266]: time="2025-06-01T11:57:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:15 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:15 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:17 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:17 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:18 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:18 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274928. Jun 01 11:57:18 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:18 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:18 theoffice go-librespot[26278]: Librespot-go daemon starting... Jun 01 11:57:19 theoffice go-librespot[26278]: time="2025-06-01T11:57:19+02:00" level=info msg="generated new device id: a159af3a34546fa4f51a833edc691665b013ac9e" Jun 01 11:57:19 theoffice go-librespot[26278]: time="2025-06-01T11:57:19+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:19 theoffice go-librespot[26278]: time="2025-06-01T11:57:19+02:00" level=debug msg="obtained new client token: AADMVbqejSsSC2wZRTbVGeH2cV2pUyojBUCTsOdvMvuhKQbo5MiTgazOtLVWMVMW1Q21YVEsj/lqN4xy7KOA2W0hoqh05IUV+lymkf1rC8lXkm+OwpiUR3PjR5/jwRwYp2X2EDsyjs0SKG/AlFNU6XMy2ZxtK8RgcZI/tLrxh+IqVllkx7kuY6Qllf2qBjN4NnAnJ4u0pqscd9RuzfqOLwf8ItYclxyjKr32S5gNy5kEnkd8FCPtTr5TYE5Y" Jun 01 11:57:19 theoffice go-librespot[26278]: time="2025-06-01T11:57:19+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:19 theoffice go-librespot[26278]: time="2025-06-01T11:57:19+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:20 theoffice go-librespot[26278]: time="2025-06-01T11:57:20+02:00" level=debug msg="completed challenge" Jun 01 11:57:20 theoffice go-librespot[26278]: time="2025-06-01T11:57:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:20 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:20 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:20 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:20 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:23 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:23 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274929. Jun 01 11:57:23 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:23 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:23 theoffice go-librespot[26300]: Librespot-go daemon starting... Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=info msg="generated new device id: 8d5a1527a3964147f03f235c314c8bee10dd90cd" Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=debug msg="obtained new client token: AACBsvUMyX9LvfN/QxAAov1W/HxAuY/mLwSKB3avTY8jm3wkZJH7fIT5ItB4o6J174KMq8SbZq2naE17BOnikpCtLtpkAbQCpEaaQQwqFmDYlgffrO9Sx3duazMlbe0Z3zvXxaX9sggV8RyHbt2pKJ6vbEkJgqynp9G0hAqk+eC8KOm//MACGEXL6rQ03fsY7JeLuXy+F6Z2ToUtLGDQKOR7cHoStxgpG9I67PZrHsaBpVslLQ5uowNe/eCyfH0=" Jun 01 11:57:23 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=debug msg="new websocket client" Jun 01 11:57:23 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:23 theoffice go-librespot[26300]: time="2025-06-01T11:57:23+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:24 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:24 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:24 theoffice volumio[953]: info: Listing playlists Jun 01 11:57:24 theoffice volumio[953]: info: Listing playlists Jun 01 11:57:24 theoffice go-librespot[26300]: time="2025-06-01T11:57:24+02:00" level=debug msg="completed challenge" Jun 01 11:57:24 theoffice go-librespot[26300]: time="2025-06-01T11:57:24+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:24 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:24 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:24 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:57:26 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:57:26 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:26 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:57:26 theoffice volumio[953]: (node:953) 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: 91679) Jun 01 11:57:26 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:57:26 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:26 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:26 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:57:27 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:27 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:27 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:27 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274930. Jun 01 11:57:27 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:27 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:27 theoffice go-librespot[26319]: Librespot-go daemon starting... Jun 01 11:57:27 theoffice go-librespot[26319]: time="2025-06-01T11:57:27+02:00" level=info msg="generated new device id: df1c05ac76fd7bcbc2217f953f81e33b98b28a8a" Jun 01 11:57:27 theoffice go-librespot[26319]: time="2025-06-01T11:57:27+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:27 theoffice go-librespot[26319]: time="2025-06-01T11:57:27+02:00" level=debug msg="obtained new client token: AAC2THC6fRdMJGcSBgetoJRmgHlNYItjaaAW3Fdh1+6ZwsUkwXajNNbE89HXH2UZRXfqi8hm3S6WvVSOA0yHmsjF+f+SyE+uaPT9Hq2yoN5Hk9ZbN4dl0f/H1CGoUNOagv6q6K3wXnGfe7uOBJHdAdhaZUTY09nyZQtGc8/ZlSOBm3Fwt2BPonILkk/tV4tpHNP/Y9SHE+nl7lH3+XW6zAKlfGKElHtBjT7lrdzu8oNb3RDgIvX3cNY87+FncM0=" Jun 01 11:57:27 theoffice go-librespot[26319]: time="2025-06-01T11:57:27+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:28 theoffice go-librespot[26319]: time="2025-06-01T11:57:28+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:28 theoffice go-librespot[26319]: time="2025-06-01T11:57:28+02:00" level=debug msg="completed challenge" Jun 01 11:57:28 theoffice go-librespot[26319]: time="2025-06-01T11:57:28+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:28 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:28 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:30 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:30 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:31 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:31 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274931. Jun 01 11:57:31 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:31 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:31 theoffice go-librespot[26342]: Librespot-go daemon starting... Jun 01 11:57:31 theoffice go-librespot[26342]: time="2025-06-01T11:57:31+02:00" level=info msg="generated new device id: 0da552e8a4be55397536e8be57e89c93165b7b7a" Jun 01 11:57:31 theoffice go-librespot[26342]: time="2025-06-01T11:57:31+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:32 theoffice go-librespot[26342]: time="2025-06-01T11:57:32+02:00" level=debug msg="obtained new client token: AADyQWXSzlNPWtNpCREefxOIsV6v2g4vF80OSjYAl2a/NEvWHqcoJkFpnGFnr/IC4qebhTSV20HkmpoFeHt4dsILVCVSOwJ2wpgkZSt+t3JjPMR0OkGRkC+BJB7JzYUNmlg0aZDPpZ/anRzQ8qinIAToRRhO5bQ5VczkhfN3x5PqzOy/5MGVCgAUVZ5mrLI4Sqiint02v1gstPCpnu0KxP6unlvK3WxiKBIBuKPs9pr7t7P02pBE42fYGOQ3" Jun 01 11:57:32 theoffice go-librespot[26342]: time="2025-06-01T11:57:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:32 theoffice go-librespot[26342]: time="2025-06-01T11:57:32+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:32 theoffice go-librespot[26342]: time="2025-06-01T11:57:32+02:00" level=debug msg="completed challenge" Jun 01 11:57:32 theoffice go-librespot[26342]: time="2025-06-01T11:57:32+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:32 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:32 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:33 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:33 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:34 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:34 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:35 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:35 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274932. Jun 01 11:57:35 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:35 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:35 theoffice go-librespot[26361]: Librespot-go daemon starting... Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=info msg="generated new device id: 77478f2a10fcaf2e7e7805ef471ce15cf867c5b0" Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=debug msg="obtained new client token: AABpwFeDVze5GF+uwQqxHoJXA/l1vD4JZNkGsqwUe5BtxN4AELnCN94nj5QTA5yPQVe0laGSmYpIsXnv55xiNTXhxvlFrhXy+URZFFP72lTw3WjsizWacTyZv5EHT7QkeoeRhvR39LD3AhX6yz4eRQsuAaz8axehZMqB+QvmWwywCV0w5WJwhrN4aIbYPgvb2mTgmfeJN7Ydk8ARcaA5elwDRi7jvMh1qQhNqmDJCX7XZhvylv99vZRy34Wz" Jun 01 11:57:36 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=debug msg="new websocket client" Jun 01 11:57:36 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:36 theoffice go-librespot[26361]: time="2025-06-01T11:57:36+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:37 theoffice go-librespot[26361]: time="2025-06-01T11:57:37+02:00" level=debug msg="completed challenge" Jun 01 11:57:37 theoffice go-librespot[26361]: time="2025-06-01T11:57:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:37 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:37 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:37 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:57:39 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:57:39 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:39 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:57:39 theoffice volumio[953]: (node:953) 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: 91680) Jun 01 11:57:39 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:57:39 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:39 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:39 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:57:40 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:40 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:40 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:40 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274933. Jun 01 11:57:40 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:40 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:40 theoffice go-librespot[26386]: Librespot-go daemon starting... Jun 01 11:57:40 theoffice go-librespot[26386]: time="2025-06-01T11:57:40+02:00" level=info msg="generated new device id: cf6d53c4f4e5ed51ab4ef69b7c1407c5895d103d" Jun 01 11:57:40 theoffice go-librespot[26386]: time="2025-06-01T11:57:40+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:40 theoffice go-librespot[26386]: time="2025-06-01T11:57:40+02:00" level=debug msg="obtained new client token: AACCqWAJWWTKiK7fp8Rjs1IeJKR0vn8E/eZ3O24l4IsARj7WOdA172y15XYirRQF1g13h42NzWW2PUF5g3OFnsZFpZzw1hcxg7gWwBnTFu7ydKKFmJTavl4V3U5k0C34w1zWibKBB0uPl3PYtFYHBDhOzV2G60HMGq+vafVpAtTvSyCZvca3hbsznsEbOU64HdGtqLB5n2Z/+MUdLPumzOcMIlwOvexrE45Y5HlVPHvP+HDuamFWobpFI46hBeE=" Jun 01 11:57:40 theoffice go-librespot[26386]: time="2025-06-01T11:57:40+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:40 theoffice go-librespot[26386]: time="2025-06-01T11:57:40+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:41 theoffice go-librespot[26386]: time="2025-06-01T11:57:41+02:00" level=debug msg="completed challenge" Jun 01 11:57:41 theoffice go-librespot[26386]: time="2025-06-01T11:57:41+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:41 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:41 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:43 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:43 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:44 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:44 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:44 theoffice volumio[953]: info: Listing playlists Jun 01 11:57:44 theoffice volumio[953]: info: Listing playlists Jun 01 11:57:44 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:44 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274934. Jun 01 11:57:44 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:44 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:44 theoffice go-librespot[26405]: Librespot-go daemon starting... Jun 01 11:57:44 theoffice go-librespot[26405]: time="2025-06-01T11:57:44+02:00" level=info msg="generated new device id: dfa0eb47619b1bd1f82fa1ae4d507487fee5d939" Jun 01 11:57:44 theoffice go-librespot[26405]: time="2025-06-01T11:57:44+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:44 theoffice go-librespot[26405]: time="2025-06-01T11:57:44+02:00" level=debug msg="obtained new client token: AAAmc4sWajK/tHZRbSJbXhaa8iYIWYEVeJgNIibE77IGeOZ/ixv3iWksKodY3g+NIJx1eFPytKmGOOealF65aga+7nIBKP4ODy8roCQpxSABrhjq3gyFG7fwTp1MXsB54bCu/cpJ/i+bF2Ttg4sF2MJgFJN1TCAGG6uqQYEVCHzdIFz7txPN71dbUqnzrFGf9gGj58QRVtIEDQ2NIDqKlg1kQCMlK+40X1vrMVdGY5+mC995+epZ84E/1OUT3Zg=" Jun 01 11:57:44 theoffice go-librespot[26405]: time="2025-06-01T11:57:44+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:45 theoffice go-librespot[26405]: time="2025-06-01T11:57:45+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:45 theoffice go-librespot[26405]: time="2025-06-01T11:57:45+02:00" level=debug msg="completed challenge" Jun 01 11:57:45 theoffice go-librespot[26405]: time="2025-06-01T11:57:45+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:45 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:45 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:46 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:46 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:48 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:48 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274935. Jun 01 11:57:48 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:48 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:48 theoffice go-librespot[26413]: Librespot-go daemon starting... Jun 01 11:57:48 theoffice go-librespot[26413]: time="2025-06-01T11:57:48+02:00" level=info msg="generated new device id: 020d7539b9ea01ff27670fb5bf0440de326447c3" Jun 01 11:57:48 theoffice go-librespot[26413]: time="2025-06-01T11:57:48+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:49 theoffice go-librespot[26413]: time="2025-06-01T11:57:49+02:00" level=debug msg="obtained new client token: AACNWJxMQ4hF6Pyb0cojJdQnyqgCpav2mtSUsMWm1v6Dz7qbrBeUXOCRL/jNOoe892q1BLtSsUEbLYJXWThkOSsmS47LGLxWOhdqAG4UlOjlQ1ReHyzn35wJXG28dn+tBRfX6dQBCTuPOknwXypuOyyxbAGw1qssE9vZhj4WfhcM3fPXV+fpxJlvZTC/rxfUcforaGslbTt+s9FgN478cFUIpvRQk9zpobkRoCHg21sxDxM4t/y6ugXcdihM" Jun 01 11:57:49 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:49 theoffice go-librespot[26413]: time="2025-06-01T11:57:49+02:00" level=debug msg="new websocket client" Jun 01 11:57:49 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:57:49 theoffice go-librespot[26413]: time="2025-06-01T11:57:49+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:49 theoffice go-librespot[26413]: time="2025-06-01T11:57:49+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Jun 01 11:57:49 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:49 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:49 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:57:52 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:57:52 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:52 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:57:52 theoffice volumio[953]: (node:953) 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: 91681) Jun 01 11:57:52 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:57:52 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:52 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:52 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:57:52 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:52 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:52 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:52 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274936. Jun 01 11:57:52 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:52 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:52 theoffice go-librespot[26436]: Librespot-go daemon starting... Jun 01 11:57:52 theoffice go-librespot[26436]: time="2025-06-01T11:57:52+02:00" level=info msg="generated new device id: 7abd6c0057c3e25421e37da19e992e1c70a30fa9" Jun 01 11:57:52 theoffice go-librespot[26436]: time="2025-06-01T11:57:52+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:52 theoffice go-librespot[26436]: time="2025-06-01T11:57:52+02:00" level=debug msg="obtained new client token: AADsCdfWC7ID9t0Cuj0oiSpQS2nFG0VnCBB89EcIL0o/eBNHblr9BhzmftSgvgy/9HNCUZyU3sAtmrCQH8j+tNuxWkBFf5NgUVkwXEH9MPpUXsYdEmFWbwpea5w6xmpuXDAbtKXR39kNBBGF0dTzjcSkI7bSmRwoK/fKz8bFXBQFtwvgZHsxm6UmbRPMvNAfhv03/prC/ggkg8TmRozhuczvsftQO7vTTB8tP4uodjpM2NQtkuCKjV41DgI/UMY=" Jun 01 11:57:52 theoffice go-librespot[26436]: time="2025-06-01T11:57:52+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:57:53 theoffice go-librespot[26436]: time="2025-06-01T11:57:53+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:53 theoffice go-librespot[26436]: time="2025-06-01T11:57:53+02:00" level=debug msg="completed challenge" Jun 01 11:57:53 theoffice go-librespot[26436]: time="2025-06-01T11:57:53+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:53 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:53 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:54 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:57:54 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:57:55 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:55 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:57:56 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:57:56 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274937. Jun 01 11:57:56 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:57:56 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:57:56 theoffice go-librespot[26455]: Librespot-go daemon starting... Jun 01 11:57:56 theoffice go-librespot[26455]: time="2025-06-01T11:57:56+02:00" level=info msg="generated new device id: f46433184439eafa43cbaa6ec865bad1516f36a6" Jun 01 11:57:56 theoffice go-librespot[26455]: time="2025-06-01T11:57:56+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:57:57 theoffice go-librespot[26455]: time="2025-06-01T11:57:57+02:00" level=debug msg="obtained new client token: AAD8MfLdodZszL0FdIFeB9y8VWwtkZkM9yZjQAjz05Fg+k4MT3Bfvtzi/a1qbVt2n06Vbsknvo4mYpDS34H5GKQv82JSsECnnr4VP+JoHOG8vfArtUMCbatrxedn4YSKIWINwjMVIICyxaFU4zfV5ElbmAvNUH16+7BYtQloBQSxg55Bs/vW95pt7lf3jYSJ818y1Jy75C9FZNYQRsg4mE4RFNUHHUQk0vR3kkbae9D1ZogVqYSuRUn57MzK" Jun 01 11:57:57 theoffice go-librespot[26455]: time="2025-06-01T11:57:57+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 11:57:57 theoffice go-librespot[26455]: time="2025-06-01T11:57:57+02:00" level=debug msg="completed keyexchange" Jun 01 11:57:57 theoffice go-librespot[26455]: time="2025-06-01T11:57:57+02:00" level=debug msg="completed challenge" Jun 01 11:57:57 theoffice go-librespot[26455]: time="2025-06-01T11:57:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:57:57 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:57:57 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:57:58 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:57:58 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:00 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:58:00 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274938. Jun 01 11:58:00 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:58:00 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:58:00 theoffice go-librespot[26518]: Librespot-go daemon starting... Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=info msg="generated new device id: 591f4582f7dd5513cc28a2b47e4e7be03a1ed0f1" Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:58:01 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=debug msg="new websocket client" Jun 01 11:58:01 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=debug msg="obtained new client token: AAAPzoQyqNTVh0ZhSG9aqmQELH9j7aR0uUXlAU8f5hvEIBCXfajahGr/2nbxwYNNQBYYfXO6FC7GVdeHt1Y/aICBlMuCf31MZtqR6twHbUIGKI89EiMZxZTa2dbwn/rrc7XuLHpPvxlj37Us6ud4VcEJFa6JaWav6ESwtc9NCoyQ8G/TemdfEYiJoMLiKMvYaPHi6TxuhgGmUr1Wx9HTL7nvCHsZL938gtYLCITaSajmINw8tmNSxUgFRqUE" Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:58:01 theoffice go-librespot[26518]: time="2025-06-01T11:58:01+02:00" level=debug msg="completed keyexchange" Jun 01 11:58:02 theoffice go-librespot[26518]: time="2025-06-01T11:58:02+02:00" level=debug msg="completed challenge" Jun 01 11:58:02 theoffice go-librespot[26518]: time="2025-06-01T11:58:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:58:02 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:58:02 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:58:02 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:58:03 theoffice volumio[953]: error: Upnp client error: Error: This socket has been ended by the other party Jun 01 11:58:04 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:04 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:04 theoffice volumio[953]: info: Listing playlists Jun 01 11:58:04 theoffice volumio[953]: info: Listing playlists Jun 01 11:58:04 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:58:04 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:04 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:58:04 theoffice volumio[953]: (node:953) 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: 91682) Jun 01 11:58:04 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:58:04 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:04 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:04 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:05 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:58:05 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:05 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:58:05 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274939. Jun 01 11:58:05 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:58:05 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:58:05 theoffice go-librespot[26528]: Librespot-go daemon starting... Jun 01 11:58:05 theoffice go-librespot[26528]: time="2025-06-01T11:58:05+02:00" level=info msg="generated new device id: f23b01c5bb712c3d22517a5e81000f375fa116ab" Jun 01 11:58:05 theoffice go-librespot[26528]: time="2025-06-01T11:58:05+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:58:05 theoffice go-librespot[26528]: time="2025-06-01T11:58:05+02:00" level=debug msg="obtained new client token: AADgmgreu0q3AJCBTvdcS+l5VREN2dnW+wj9hrdespU4VNl7pEDPs7DvL/wCpj7G50j6PMnLy1OH8SEU1amWdCCWYbMmg7vql5U1hL14fzeqcPNBF6tcyRFkI9pQsTOQBoo0amcYIUfPHWfYJVtJ+Lnu/axJ0IRohtCSmwhx97JR8wCu6E3rYJPbHzZ2CDucKBRWqVjRlr6+PTMk0OOArur90q2OCHT6jPjYKt3oX4C8WuxjeUlh0+q/ZAb2khw=" Jun 01 11:58:05 theoffice go-librespot[26528]: time="2025-06-01T11:58:05+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:58:05 theoffice go-librespot[26528]: time="2025-06-01T11:58:05+02:00" level=debug msg="completed keyexchange" Jun 01 11:58:06 theoffice go-librespot[26528]: time="2025-06-01T11:58:06+02:00" level=debug msg="completed challenge" Jun 01 11:58:06 theoffice go-librespot[26528]: time="2025-06-01T11:58:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:58:06 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:58:06 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:58:06 theoffice volumio[953]: info: Clearing queue after UPNP request Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::ClearQueue Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::clearPlayQueue Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::saveQueue Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushQueue Jun 01 11:58:07 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:07 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:07 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 41ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 15ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 8ms Jun 01 11:58:07 theoffice volumio[953]: info: Starting UPNP Playback Jun 01 11:58:07 theoffice volumio[953]: info: Preparing playback through UPNP Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 5ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 5ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:07 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: options Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: options Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 5 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 4 milliseconds Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:07 theoffice volumio[953]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 01 11:58:07 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState stateService stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: No code Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:07 theoffice volumio[953]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 01 11:58:07 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState stateService stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: No code Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 52ms Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 49ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: options Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 3 milliseconds Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:07 theoffice volumio[953]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jun 01 11:58:07 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState stateService stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus stop Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: No code Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 21ms Jun 01 11:58:07 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:07 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 28 milliseconds Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 30 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 28 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 3 milliseconds Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:07 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:07 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:07 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:07 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:07 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus stop Jun 01 11:58:07 theoffice volumio[953]: info: ------------------------------ 39ms Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: Jun 01 11:58:07 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 12 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 11 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 6 milliseconds Jun 01 11:58:07 theoffice volumio[953]: info: sendMpdCommand status took 5 milliseconds Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:07 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:07 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:08 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:08 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":84,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:08 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:08 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:08 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:08 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:08 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":672,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:08 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:08 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:08 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:08 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:08 theoffice volumio[953]: info: ------------------------------ 55ms Jun 01 11:58:08 theoffice volumio[953]: info: ------------------------------ 54ms Jun 01 11:58:08 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 11 milliseconds Jun 01 11:58:08 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 10 milliseconds Jun 01 11:58:08 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 9 milliseconds Jun 01 11:58:08 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:08 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:08 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:08 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:08 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:08 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:08 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:08 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:08 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:08 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:08 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:08 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:08 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:08 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:08 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:08 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"pLBf-X_qM0Bs6TRkzZh2WQ.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/pLBf-X_qM0Bs6TRkzZh2WQ.mp3","trackType":"mp3"} Jun 01 11:58:08 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:08 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:08 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:08 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:08 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:08 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:08 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:08 theoffice volumio[953]: info: ------------------------------ 35ms Jun 01 11:58:08 theoffice volumio[953]: info: ------------------------------ 28ms Jun 01 11:58:08 theoffice volumio[953]: info: ------------------------------ 26ms Jun 01 11:58:08 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:58:08 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:09 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:58:09 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274940. Jun 01 11:58:09 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:58:09 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:58:09 theoffice go-librespot[26573]: Librespot-go daemon starting... Jun 01 11:58:09 theoffice go-librespot[26573]: time="2025-06-01T11:58:09+02:00" level=info msg="generated new device id: 04bd92e9e3afb06264c1491bb33a0cd4536152a1" Jun 01 11:58:09 theoffice go-librespot[26573]: time="2025-06-01T11:58:09+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:58:09 theoffice go-librespot[26573]: time="2025-06-01T11:58:09+02:00" level=debug msg="obtained new client token: AAA7n4qpct2a0wRV+HRSe7eU3mSGyZOTgA88v69vsELtH8m/t8fWAuhmIO++r0lrtlqVyoDXQTOIx1/mz2w0r+3QASyQvIrsZ7aWdXjsN3AVi+v6xGp9ECiuNzuF0CcDqa1ETz7Sk1mqjHNUn0A6gnpMFkdpehGKmA8lODMDJMaKdlUYtjTEdnhV0XMlemE98xm7hAPLirPrWAAD9UcADDCpBYeTj1PuiULlLn6x4cUxrmflZk5WppM1Bq8aj+0=" Jun 01 11:58:09 theoffice go-librespot[26573]: time="2025-06-01T11:58:09+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:58:10 theoffice go-librespot[26573]: time="2025-06-01T11:58:10+02:00" level=debug msg="completed keyexchange" Jun 01 11:58:10 theoffice volumio[953]: info: Jun 01 11:58:10 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:10 theoffice volumio[953]: info: Jun 01 11:58:10 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:10 theoffice volumio[953]: info: Jun 01 11:58:10 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:10 theoffice volumio[953]: info: sendMpdCommand status took 4 milliseconds Jun 01 11:58:10 theoffice volumio[953]: info: sendMpdCommand status took 3 milliseconds Jun 01 11:58:10 theoffice volumio[953]: info: sendMpdCommand status took 2 milliseconds Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:10 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 01 11:58:10 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 3 milliseconds Jun 01 11:58:10 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:10 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:10 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:10 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:10 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:10 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:10 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:10 theoffice volumio[953]: info: ------------------------------ 20ms Jun 01 11:58:10 theoffice volumio[953]: info: ------------------------------ 17ms Jun 01 11:58:10 theoffice volumio[953]: info: ------------------------------ 16ms Jun 01 11:58:10 theoffice go-librespot[26573]: time="2025-06-01T11:58:10+02:00" level=debug msg="completed challenge" Jun 01 11:58:10 theoffice go-librespot[26573]: time="2025-06-01T11:58:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:58:10 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:58:10 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:58:10 theoffice volumio[953]: info: Clearing queue after UPNP request Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::ClearQueue Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::stop Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::stPlaybackTimer Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::updateTrackBlock Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrackBlock Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::serviceStop Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::stop Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand stop Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::clearPlayQueue Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::saveQueue Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::volumioPushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::volumioPushQueue Jun 01 11:58:11 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:11 theoffice volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand stop took 13 milliseconds Jun 01 11:58:11 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Starting UPNP Playback Jun 01 11:58:11 theoffice volumio[953]: info: Preparing playback through UPNP Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 01 11:58:11 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:58:11 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:11 theoffice volumio[953]: error: updateQueue error: null Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 23ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 22ms Jun 01 11:58:11 theoffice volumio[953]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 2ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces system playlist update Jun 01 11:58:11 theoffice volumio[953]: info: Ignoring MPD Status Update Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 4ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 3ms Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 25 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 24 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 23 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: info: Jun 01 11:58:11 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 7 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 6 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 6 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 7 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 4 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand status took 3 milliseconds Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus stop Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":420,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:11 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":420,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:11 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 44ms Jun 01 11:58:11 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:11 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 42ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 40ms Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 9 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 9 milliseconds Jun 01 11:58:11 theoffice volumio[953]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: verbose: ControllerMpd::parseTrackInfo Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:11 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:11 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:11 theoffice volumio[953]: verbose: In UPNP mode Jun 01 11:58:11 theoffice volumio[953]: verbose: STATE SERVICE {"status":"play","position":0,"seek":924,"duration":0,"samplerate":"24 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"48 Kbps","isStreaming":false,"title":"Lq-CMh8uoNMPwz6faS4KQg.mp3","artist":null,"album":" Home Assistant","uri":"http://192.168.77.113:8123/api/tts_proxy/Lq-CMh8uoNMPwz6faS4KQg.mp3","trackType":"mp3"} Jun 01 11:58:11 theoffice volumio[953]: verbose: CURRENT POSITION 0 Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState stateService play Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::syncState currentStatus play Jun 01 11:58:11 theoffice volumio[953]: info: Received an update from plugin. extracting info from payload Jun 01 11:58:11 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:11 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:11 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:11 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:11 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 33ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 23ms Jun 01 11:58:11 theoffice volumio[953]: info: ------------------------------ 22ms Jun 01 11:58:13 theoffice systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 11:58:13 theoffice systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 274941. Jun 01 11:58:13 theoffice systemd[1]: Stopped go-librespot Daemon. Jun 01 11:58:13 theoffice systemd[1]: Started go-librespot Daemon. Jun 01 11:58:13 theoffice go-librespot[26630]: Librespot-go daemon starting... Jun 01 11:58:13 theoffice go-librespot[26630]: time="2025-06-01T11:58:13+02:00" level=info msg="generated new device id: 58149ee0c3ccfa7e2900092df93a9e78beac4818" Jun 01 11:58:13 theoffice go-librespot[26630]: time="2025-06-01T11:58:13+02:00" level=debug msg="stored credentials found for kandersen" Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=debug msg="obtained new client token: AAApAKlcD37TqAcqKgp+Vrax/4rvG4hlsymnH1SGqzMyYT1tiyiuw7qrc7LMEJyFigBDCVXH2mEtALu22C/4B+Jfd/0sgyC+dEUqg3x9BXZgcEVCLMg4VK3vW83E8QiB9C2+WbcFgcdKOQhgnWYXdh+gSFErdPn34ewIvQ/3iD0I1qs5IctTj5N2if1mBeIiiJMDOXwRUO7n5ericGx9JM98jobIuNPLTl/KwmXGIv8iF2hXWJ9SqUvItbqO" Jun 01 11:58:14 theoffice volumio[953]: info: Initializing connection to go-librespot Websocket Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=debug msg="new websocket client" Jun 01 11:58:14 theoffice volumio[953]: info: Connection to go-librespot Websocket established Jun 01 11:58:14 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:14 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:14 theoffice volumio[953]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:14 theoffice volumio[953]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Jun 01 11:58:14 theoffice volumio[953]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Jun 01 11:58:14 theoffice volumio[953]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Jun 01 11:58:14 theoffice volumio[953]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Jun 01 11:58:14 theoffice volumio[953]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Jun 01 11:58:14 theoffice volumio[953]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Jun 01 11:58:14 theoffice volumio[953]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Jun 01 11:58:14 theoffice volumio[953]: at /volumio/node_modules/express/lib/router/index.js:281:22 Jun 01 11:58:14 theoffice volumio[953]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Jun 01 11:58:14 theoffice volumio[953]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Jun 01 11:58:14 theoffice volumio[953]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Jun 01 11:58:14 theoffice volumio[953]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Jun 01 11:58:14 theoffice volumio[953]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Jun 01 11:58:14 theoffice volumio[953]: at /volumio/node_modules/express/lib/router/index.js:284:7 Jun 01 11:58:14 theoffice volumio[953]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Jun 01 11:58:14 theoffice volumio[953]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=debug msg="completed keyexchange" Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=debug msg="completed challenge" Jun 01 11:58:14 theoffice go-librespot[26630]: time="2025-06-01T11:58:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jun 01 11:58:14 theoffice systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 11:58:14 theoffice systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 11:58:14 theoffice volumio[953]: info: Connection to go-librespot Websocket closed Jun 01 11:58:16 theoffice volumio[953]: info: Jun 01 11:58:16 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:16 theoffice volumio[953]: info: Jun 01 11:58:16 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:16 theoffice volumio[953]: info: Jun 01 11:58:16 theoffice volumio[953]: ---------------------------- MPD announces state update: player Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::getState Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::sendMpdCommand status Jun 01 11:58:16 theoffice volumio[953]: info: sendMpdCommand status took 4 milliseconds Jun 01 11:58:16 theoffice volumio[953]: info: sendMpdCommand status took 3 milliseconds Jun 01 11:58:16 theoffice volumio[953]: info: sendMpdCommand status took 2 milliseconds Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:16 theoffice volumio[953]: verbose: ControllerMpd::parseState Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:16 theoffice volumio[953]: info: ControllerMpd::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreCommandRouter::servicePushState Jun 01 11:58:16 theoffice volumio[953]: info: CoreStateMachine::pushState Jun 01 11:58:16 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:16 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:16 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:16 theoffice volumio[953]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:16 theoffice volumio[953]: info: ------------------------------ 13ms Jun 01 11:58:16 theoffice volumio[953]: info: ------------------------------ 12ms Jun 01 11:58:16 theoffice volumio[953]: info: ------------------------------ 11ms Jun 01 11:58:17 theoffice volumio[953]: info: Getting Spotify volume Jun 01 11:58:17 theoffice volumio[953]: (node:953) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 11:58:17 theoffice volumio[953]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jun 01 11:58:17 theoffice volumio[953]: (node:953) 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: 91683) Jun 01 11:58:17 theoffice volumio[953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 11:58:17 theoffice volumio[953]: info: CoreCommandRouter::volumioGetState Jun 01 11:58:17 theoffice volumio[953]: info: CorePlayQueue::getTrack 0 Jun 01 11:58:17 theoffice volumio[953]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 11:58:17 theoffice volumio[953]: TypeError: Cannot read property 'name' of undefined Jun 01 11:58:17 theoffice volumio[953]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Jun 01 11:58:17 theoffice volumio[953]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Jun 01 11:58:17 theoffice volumio[953]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Jun 01 11:58:17 theoffice volumio[953]: at Socket.emit (events.js:315:20) Jun 01 11:58:17 theoffice volumio[953]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Jun 01 11:58:17 theoffice volumio[953]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jun 01 11:58:17 theoffice volumio[953]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 11:58:17 theoffice sudo[26671]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-01 11:57 Jun 01 11:58:17 theoffice sudo[26671]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"