-- Logs begin at Mon 2025-02-24 21:39:00 CET, end at Mon 2025-02-24 23:20:31 CET. -- Feb 24 23:19:01 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:01 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2344. Feb 24 23:19:02 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:02 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:02 minidsp-shd go-librespot[27982]: Librespot-go daemon starting... Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=info msg="generated new device id: 63927e8f3592b6ab21b0f2dafcddda5c1aef0e17" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="zeroconf server listening on port 40267" Feb 24 23:19:02 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:02+01:00" level=debug msg="obtained new client token: AAAmolgKIH1Vl20JVPtsk1sjwxAvEYtvldMdFsomZTf0TWqUuh/BuvOaiUGt5IrJxb7M2Uscw/AnlCT7cVUHfbAidFTO129A7TpZJsV4e0+UouyOpFjz+837ahTji5UC3pamh8uJCBRnZUhMSoDX/FXO4SIWYzQQtne5cQ9W96MzuM3Au2HAPxXli3NZpeJSugIQYoARVeFYvamGdSLXrmJsL+wGKI18pl2Ry0U8wbJ8U35h7io0pstyTx75yA==" Feb 24 23:19:03 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:03+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:03 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:03+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:03 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:03+01:00" level=debug msg="completed challenge" Feb 24 23:19:03 minidsp-shd go-librespot[27982]: time="2025-02-24T23:19:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:04 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:04 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2345. Feb 24 23:19:06 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:06 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:06 minidsp-shd go-librespot[27990]: Librespot-go daemon starting... Feb 24 23:19:06 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:06+01:00" level=info msg="generated new device id: dbffa6b546b10f635854a39a33678158571443f1" Feb 24 23:19:06 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:06+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="zeroconf server listening on port 46527" Feb 24 23:19:07 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="new websocket client" Feb 24 23:19:07 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket established Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="obtained new client token: AADsomh3PDGm+u+9aHAugRF00q1LAdN0yJrujwnQo4fxOr0KNX2LxkKsE1gRORlMhasO7JwaLnaeVswQivPc3m5BUrr+Y++x4xa2n2sUQjIn8BerPi+EJvpOQ2lA7IGAAMzvfTLMF0vvZ/J8YC5+GZaQ7W0hntIoEn6uRSSUawcejouIFXYYPt+GwvsHDJUFjJs87WnGHIaGWpW8tpOochUzkbe+1OGkWjeWe+0A7lX2dPj5RIbivKqktAg=" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=debug msg="completed challenge" Feb 24 23:19:07 minidsp-shd go-librespot[27990]: time="2025-02-24T23:19:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:07 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket closed Feb 24 23:19:10 minidsp-shd volumio[30763]: info: Getting Spotify volume Feb 24 23:19:10 minidsp-shd volumio[30763]: (node:30763) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:10 minidsp-shd volumio[30763]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 23:19:10 minidsp-shd volumio[30763]: (node:30763) 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: 776) Feb 24 23:19:10 minidsp-shd volumio[30763]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 23:19:10 minidsp-shd volumio[30763]: info: CoreCommandRouter::volumioGetState Feb 24 23:19:10 minidsp-shd volumio[30763]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 23:19:10 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:10 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2346. Feb 24 23:19:10 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:10 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:11 minidsp-shd go-librespot[27998]: Librespot-go daemon starting... Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=info msg="generated new device id: 3f237c01ec917d80bfd40baee37535b4b68d7cf3" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="zeroconf server listening on port 39005" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="obtained new client token: AADTGLbWZv1c5sJYNss5pywhdNu8GHiTT9tspuyXUGXfnewwvDYbNSlZmxvlkWRNNrXtMi7/QIg8ROpuu8ba3a0md/j3j5FRacwFmDQNlvz41S4s5TDjoqLoMdqBMBrQEK4jgnCgZMvY8BA+zgiecy2pqGrPl+bQPCNhVGDGFmtJ7yfiOyhW6AyHVq5ECb2LqAA6Ta82niD7HLJBOvjTQ1c5hdMBzm0Rm1YaJnGitmQEfU+RygJK/OFJl5KfCw==" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:11 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:11+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:12 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:12+01:00" level=debug msg="completed challenge" Feb 24 23:19:12 minidsp-shd go-librespot[27998]: time="2025-02-24T23:19:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:12 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:12 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:13 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:13 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:15 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:15 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:15 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:15 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2347. Feb 24 23:19:15 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:15 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:15 minidsp-shd go-librespot[28006]: Librespot-go daemon starting... Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=info msg="generated new device id: c6a14c98778c99e7a1edfe111b0f28a60cb81500" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="zeroconf server listening on port 46609" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="obtained new client token: AAAcq/ciOrzTAkSWGTvGXdty7KSDiVb1gEZYFr6uMFHlQiDm22+rSk8KuuCkHfigMxMh5NlopNvxaxy2I7ePt+oEyGd5SXAmyr5O4rLWaRgSlS7M2uwZlmb6eLi4m99E9hYpBQrTympf1k6TbZzjumPfM7Kds3x9zAeQ9fU6zYoMYL61FzMr1LNSJBv2ge3z1VzJIiuluOLNuctAxarulbup1Rc0HztEOnv9m3ZSw36tpiFxZRipXcK4S9zhaQ==" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:15 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:15+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:16 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:16+01:00" level=debug msg="completed challenge" Feb 24 23:19:16 minidsp-shd go-librespot[28006]: time="2025-02-24T23:19:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:16 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:16 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:17 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:17 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:17 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:17 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:17 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:17 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:17 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:17 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2348. Feb 24 23:19:19 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:19 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:19 minidsp-shd go-librespot[28014]: Librespot-go daemon starting... Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=info msg="generated new device id: 05ca2e24a8df61a12eec88e68dcbbe5055165ca2" Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="zeroconf server listening on port 46489" Feb 24 23:19:19 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="new websocket client" Feb 24 23:19:19 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket established Feb 24 23:19:19 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:19+01:00" level=debug msg="obtained new client token: AACOmFHdUuJSaXJGhdsQt+rai801gmAGBzkUL9qs6cV6js75MXqJIlOKG0MVIiK0teZCjdrsUqomt5p95HXjUEsw6TriDzKN9U9K/ZlSW0IR0JTh9Z7ARj6bW2L6GbrnvqS5Qj42iQD6tilJsR07ETz/l9hOjxK88dqPi8LM+KaD15kxO6Tm/ep3sTBVEIUzokHShMqBYctFpqfxGttW/bh5rqdMI9cLFLKhgiWaBaPOzHXfGeMy2AHb7uqXEg==" Feb 24 23:19:20 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:20+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:20 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:20+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:20 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:20+01:00" level=debug msg="completed challenge" Feb 24 23:19:20 minidsp-shd go-librespot[28014]: time="2025-02-24T23:19:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:20 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket closed Feb 24 23:19:22 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:22 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:22 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:22 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:22 minidsp-shd volumio[30763]: info: Getting Spotify volume Feb 24 23:19:22 minidsp-shd volumio[30763]: (node:30763) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:22 minidsp-shd volumio[30763]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 23:19:22 minidsp-shd volumio[30763]: (node:30763) 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: 777) Feb 24 23:19:22 minidsp-shd volumio[30763]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 23:19:22 minidsp-shd volumio[30763]: info: CoreCommandRouter::volumioGetState Feb 24 23:19:22 minidsp-shd volumio[30763]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 23:19:23 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:23 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:23 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:23 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:23 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:23 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2349. Feb 24 23:19:23 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:23 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:23 minidsp-shd go-librespot[28023]: Librespot-go daemon starting... Feb 24 23:19:23 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:23+01:00" level=info msg="generated new device id: 0732e0b83127737e2bee810c1c2a1ce647b3db5c" Feb 24 23:19:23 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:23+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="zeroconf server listening on port 33463" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="obtained new client token: AACEeM+EEwIPu5zArQsk5qKrm6hMgaBikfnvt3oFKTK2s9SyiW09vuPgRgpjOyoBRCYGYKlffIEtSEJN+7ysC2IVsiJTAJDmKR3UKPs+uA563BNTLRnVKU8s/wyKECzYJBw+8VwBBv3igEUvW1B2Q/m7nj9XMqJf1qQFlCOyhouUgqpYra+hORHlfCuXnq1KQpt8wBjPpuyWMqt1Nv+705oV3Tsq2qEGwDqBR0Nz4qYi+UuJM07ETbCvJ9w=" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:24 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:24 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:24 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:24 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=debug msg="completed challenge" Feb 24 23:19:24 minidsp-shd go-librespot[28023]: time="2025-02-24T23:19:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:25 minidsp-shd volumio[30763]: Searching plugin music_service/last_100 Feb 24 23:19:25 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:25 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:25 minidsp-shd volumio[30763]: info: All search sources collected, pushing search results Feb 24 23:19:26 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:26 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2350. Feb 24 23:19:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:28 minidsp-shd go-librespot[28033]: Librespot-go daemon starting... Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=info msg="generated new device id: a2c3f1e4d5adf5d1469964ffc720f4455580b07e" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="zeroconf server listening on port 40373" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="obtained new client token: AACGZn6rgXGOCFqZze4geqyJs4olC2/VXygx+QG9lEStpZdCLrf6Adl0QGWHlD5WFrkQ6ZUC2jc80y2PMzPZn9w7CKXt3mGnyu18wm4BOktPFtC3V4e9v/NhqOZcV9URTo8boCKb/NX7icGwwusoJZbjfyZfFL9ctVTt7sinhHXyuNsCAa6Pc6l3Zis1K9p2GxiO8P4tgilkS3OLuK1QaH+DZclMgeyLorMMPcKAFSOeTkF9jkLwdauoc5zy2A==" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:28 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:28+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:29 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:29+01:00" level=debug msg="completed challenge" Feb 24 23:19:29 minidsp-shd go-librespot[28033]: time="2025-02-24T23:19:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:29 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:29 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2351. Feb 24 23:19:32 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:32 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:32 minidsp-shd go-librespot[28041]: Librespot-go daemon starting... Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=info msg="generated new device id: a27811d03caca0ccd75068ed9809fb4e8286aa10" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="zeroconf server listening on port 40691" Feb 24 23:19:32 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="new websocket client" Feb 24 23:19:32 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket established Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="obtained new client token: AADqOuX0ixlj1N42wkZ0NVhNcfTjTbZTSIGw/yc4KbsMkK3j7rcjZex7Or7kFHUt8ESZ+BHkfMYgEJqfMEUh5T/Vyn8Y68G4jbWnw6Pg5W3oCaVAC3uOdw8MDLDNEhS1U9GQvrYgPQ5f8tHUzzSbQsNt+kqr1ntBGjf7Ak/9ALEyM8/j/LUsy8ZRn+8VyWEEood3wST0frOXkmMZOl+yEnLj6RecQ9MgkuzUUdQ8pAqzZXLfKgftZonBjjokKA==" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:32 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:32+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:33 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:33+01:00" level=debug msg="completed challenge" Feb 24 23:19:33 minidsp-shd go-librespot[28041]: time="2025-02-24T23:19:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:33 minidsp-shd volumio[30763]: info: Connection to go-librespot Websocket closed Feb 24 23:19:35 minidsp-shd volumio[30763]: info: Getting Spotify volume Feb 24 23:19:35 minidsp-shd volumio[30763]: (node:30763) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:35 minidsp-shd volumio[30763]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 23:19:35 minidsp-shd volumio[30763]: (node:30763) 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: 778) Feb 24 23:19:35 minidsp-shd volumio[30763]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 23:19:35 minidsp-shd volumio[30763]: info: CoreCommandRouter::volumioGetState Feb 24 23:19:35 minidsp-shd volumio[30763]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 23:19:36 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:36 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2352. Feb 24 23:19:36 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:36 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:36 minidsp-shd go-librespot[28049]: Librespot-go daemon starting... Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=info msg="generated new device id: 7fc451a3bb91e58352e5af1a4a088378a0be6df8" Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:36 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:36+01:00" level=debug msg="zeroconf server listening on port 41119" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=debug msg="obtained new client token: AAAkxquOSLBNSo00Ch7heintyGUwAWQHRVAmpawx6yK4ftDTTtfZUO98E8Q13uOIHb5BFucK1oab92Xtol7TJSvwXmIfnj8m+sAzP32NoEPBLURh+WRWgpLtX9PcGiHdF33Ix8jjHc3IqY7VWnVm9PITesQrYxJlfAy3Ixo227SjzapI6yu4sy3lb/fp4xgyQ9jFdFeMQMCswPbQekjdnbxEchnsoAGlkH99MjLrf1m7JhabNt5qYXj6Wl6EzQ==" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=debug msg="completed challenge" Feb 24 23:19:37 minidsp-shd go-librespot[28049]: time="2025-02-24T23:19:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:39 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:39 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2353. Feb 24 23:19:40 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:40 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:41 minidsp-shd go-librespot[28057]: Librespot-go daemon starting... Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=info msg="generated new device id: 76ed50f794e7e571c908497302a44f200ae3daf1" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="zeroconf server listening on port 44263" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="obtained new client token: AACaz3Fj2A8Vcvg3IEGQiMeH3l++Urh0zKUXlNN/yPbS4SmAP88yIkbNQrgIFSCEimbAHqQOKVm8o/mSWZVeuvJY2A72PTYO974tN3fYw6v56lkIAdnYgl2d5Y3Oc4zASv9rCwdtiFZcz8PZzTTrk3Ry6MT6ajy+tDhATItV1aCyd/IM10vMLTxXtQHjxg+Oqt9nVg39cRnV+lg2qyNkbCLX/glasUVrRFyfwSxtys8KzKGdBdZM2PdvpHd0Yg==" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:41 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:41+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:42 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:42+01:00" level=debug msg="completed challenge" Feb 24 23:19:42 minidsp-shd go-librespot[28057]: time="2025-02-24T23:19:42+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:42 minidsp-shd volumio[30763]: info: Initializing connection to go-librespot Websocket Feb 24 23:19:42 minidsp-shd volumio[30763]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:19:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2354. Feb 24 23:19:45 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:45 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:45 minidsp-shd go-librespot[28066]: Librespot-go daemon starting... Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=info msg="generated new device id: 7dbd54a1ce3cb9853a7766a867caba5b5502a5d6" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:45 minidsp-shd volumio[30763]: Searching all installed plugins Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: webradio , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Feb 24 23:19:45 minidsp-shd volumio[30763]: info: [1740435585353] ControllerCalmRadio::searchCategories Feb 24 23:19:45 minidsp-shd volumio[30763]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:19:45 minidsp-shd volumio[30763]: TypeError: Cannot read property 'cats' of undefined Feb 24 23:19:45 minidsp-shd volumio[30763]: at ControllerCalmRadio.searchCategories (/data/plugins/music_service/calmradio/index.js:615:42) Feb 24 23:19:45 minidsp-shd volumio[30763]: at ControllerCalmRadio.search (/data/plugins/music_service/calmradio/index.js:665:28) Feb 24 23:19:45 minidsp-shd volumio[30763]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Feb 24 23:19:45 minidsp-shd volumio[30763]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Feb 24 23:19:45 minidsp-shd volumio[30763]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Feb 24 23:19:45 minidsp-shd volumio[30763]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Feb 24 23:19:45 minidsp-shd volumio[30763]: at Socket.emit (events.js:400:28) Feb 24 23:19:45 minidsp-shd volumio[30763]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 24 23:19:45 minidsp-shd volumio[30763]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Feb 24 23:19:45 minidsp-shd volumio[30763]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="zeroconf server listening on port 43281" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="obtained new client token: AABoRWf1SvGoWVkn1Wok4CTQFpA8gbON3PC1hPVhjoamPTSDMUSXSx0rfQtM0sD+PtqE0CahVNFCxoeL2DxCYHe70SqGLfpxv7KKq00K1BxUZr5/xEXHyn/tHv5k5qOU7cHAEZImQd0U4w8tkw84Pzhnu6GdmLbfL7ZGFG2WekIbqW0wPFQLC+DoINxWBgHxgNWpKhHTgBnyDkKi7MxfigqYUgCvfuFGUkPanSy8ZF8b4dNNIInqloA56F23qg==" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:45 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:45+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:46 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:46+01:00" level=debug msg="completed challenge" Feb 24 23:19:46 minidsp-shd sudo[28083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 23:18 Feb 24 23:19:46 minidsp-shd sudo[28083]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:19:46 minidsp-shd go-librespot[28066]: time="2025-02-24T23:19:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:46 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:46 minidsp-shd sudo[28083]: pam_unix(sudo:session): session closed for user root Feb 24 23:19:46 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:19:46] [info] asio async_read_at_least error: system:104 (Connection reset by peer) Feb 24 23:19:46 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:19:46] [error] handle_read_frame error: websocketpp.transport:2 (Underlying Transport Error) Feb 24 23:19:46 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:19:46] [disconnect] Disconnect close local:[1006,Underlying Transport Error] remote:[1006] Feb 24 23:19:46 minidsp-shd vtcs[31163]: [2025-02-24 23:19:46.690] [tisoc] [error] [SpkconServer.cpp:377] recv error. socket disconnected Feb 24 23:19:46 minidsp-shd systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:46 minidsp-shd systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 24 23:19:46 minidsp-shd systemd[1]: Started dynamicswap service. Feb 24 23:19:46 minidsp-shd systemd[1]: dynamicswap.service: Succeeded. Feb 24 23:19:46 minidsp-shd systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Feb 24 23:19:46 minidsp-shd systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Feb 24 23:19:46 minidsp-shd systemd[1]: Started dynamicswap service. Feb 24 23:19:47 minidsp-shd systemd[1]: Stopped Volumio Backend Module. Feb 24 23:19:47 minidsp-shd systemd[1]: Started Volumio Backend Module. Feb 24 23:19:47 minidsp-shd systemd[1]: dynamicswap.service: Succeeded. Feb 24 23:19:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2355. Feb 24 23:19:49 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:49 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:49 minidsp-shd go-librespot[28106]: Librespot-go daemon starting... Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=info msg="generated new device id: 9ad5f0ec6b0a30d44a954b7692c6066cd13de264" Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:49 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:49+01:00" level=debug msg="zeroconf server listening on port 40601" Feb 24 23:19:50 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:50+01:00" level=debug msg="obtained new client token: AAD1bwptNsijIYRcKLKUXNYELXuotS4ophR5dbFsuaNIz8fmy0jpE2VezSn0pmObuHikYmzv07QrXXhptijuWF0xWT+ZmhPQPdjBF6q2NcmvYI8SCiDV1SBY7AWM/K1wNPEpBtT4zaWMj3/zXX2nCG1ld1wtQg99AsLrHInwu4cJ8sPBYnPdaq/g0mu1jG+ZgFB183PSS2l8FFwxDZ1cwCVFDAcAUNgMQQf55L72ggMQiwPvx/uKjR2RNPA=" Feb 24 23:19:50 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:50+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:50 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:50+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:50 minidsp-shd volumio[28094]: info: ------------------------------------------- Feb 24 23:19:50 minidsp-shd volumio[28094]: info: ----- Volumio3 ---- Feb 24 23:19:50 minidsp-shd volumio[28094]: info: ------------------------------------------- Feb 24 23:19:50 minidsp-shd volumio[28094]: info: ----- System startup ---- Feb 24 23:19:50 minidsp-shd volumio[28094]: info: ------------------------------------------- Feb 24 23:19:50 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:50+01:00" level=debug msg="completed challenge" Feb 24 23:19:50 minidsp-shd go-librespot[28106]: time="2025-02-24T23:19:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:51 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:19:51] [connect] Successful connection Feb 24 23:19:51 minidsp-shd volumio[28094]: info: MYVOLUMIO Environment detected Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Plugin folders cleanup Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning into folder /volumio/app/plugins/ Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category audio_interface Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category miscellanea Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category music_service Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category plugins.json Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category system_controller Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category user_interface Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning into folder /data/plugins/ Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Scanning category music_service Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Plugin folders cleanup completed Feb 24 23:19:51 minidsp-shd volumio[28094]: info: ------------------------------------------- Feb 24 23:19:51 minidsp-shd volumio[28094]: info: ----- Core plugins startup ---- Feb 24 23:19:51 minidsp-shd volumio[28094]: info: ------------------------------------------- Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Loading plugins from folder /volumio/app/plugins/ Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin bluetooth to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin multiroom to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin upnp to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin metavolumio to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin ms_surface_dial to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin cd_controller to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin raat to MyMusic Plugins Feb 24 23:19:51 minidsp-shd volumio[28094]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 24 23:19:52 minidsp-shd volumio[28094]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 24 23:19:52 minidsp-shd volumio[28094]: info: Loading plugins from folder /data/plugins/ Feb 24 23:19:52 minidsp-shd volumio[28094]: info: Loading plugin "system"... Feb 24 23:19:52 minidsp-shd volumio[28094]: info: Loading plugin "appearance"... Feb 24 23:19:53 minidsp-shd volumio[28094]: info: Loading plugin "network"... Feb 24 23:19:53 minidsp-shd volumio[28094]: info: Refreshing Cached IP Addresses Feb 24 23:19:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2356. Feb 24 23:19:53 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:54 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:54 minidsp-shd go-librespot[28170]: Librespot-go daemon starting... Feb 24 23:19:54 minidsp-shd sudo[28169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:19:54 minidsp-shd sudo[28169]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:19:54 minidsp-shd sudo[28169]: pam_unix(sudo:session): session closed for user root Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=info msg="generated new device id: bef7419aebe1dd5a99e26f40654abd1b1fabebef" Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "services"... Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:54 minidsp-shd sudo[28173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:19:54 minidsp-shd sudo[28173]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "alsa_controller"... Feb 24 23:19:54 minidsp-shd sudo[28181]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 24 23:19:54 minidsp-shd sudo[28181]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:19:54 minidsp-shd sudo[28173]: pam_unix(sudo:session): session closed for user root Feb 24 23:19:54 minidsp-shd sudo[28181]: pam_unix(sudo:session): session closed for user root Feb 24 23:19:54 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "wizard"... Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "networkfs"... Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Starting Udev Watcher for removable devices Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Ignoring mount for partition: BOOT Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Ignoring mount for partition: volumio Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Ignoring mount for partition: volumio_data Feb 24 23:19:54 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "volumio_command_line_client"... Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "upnp"... Feb 24 23:19:54 minidsp-shd volumio[28094]: info: [1740435594468] Starting Upmpd Daemon Feb 24 23:19:54 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "my_music"... Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:54 minidsp-shd volumio[28094]: info: Loading plugin "mpd"... Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="zeroconf server listening on port 36287" Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="obtained new client token: AADYhXyLjxmYYh3a6vT6CcQxt3sJVwnzvGWGUe1Ynxdjmi5vxksil8i1Z0tcUQyrw9zJ8+Uj4kaqeKsnI/CXKlh9yhxBCY2K72kKPykSk+NiFyvMsoHwMx/NaKigPFvR1p/VdBglENiTeJ5aJMz5cAbIvKzztdmWx3w+heRr5UxV7GkqdtGVdworYlwtRju0rqDcvfc0D4ZL1tRYRT0PKWcjHKjC/cjEkNbOPZvK8dIcetG1Igtmo46KayRYTQ==" Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:54 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:54+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:55 minidsp-shd volumio[28094]: info: Loading plugin "upnp_browser"... Feb 24 23:19:55 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:55+01:00" level=debug msg="completed challenge" Feb 24 23:19:55 minidsp-shd go-librespot[28170]: time="2025-02-24T23:19:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:55 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:55 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:19:55 minidsp-shd volumio[28094]: info: Loading plugin "bluetooth"... Feb 24 23:19:56 minidsp-shd volumio[28094]: info: [1740435596064] Starting BluetoothController Feb 24 23:19:56 minidsp-shd volumio[28094]: info: Loading plugin "alarm-clock"... Feb 24 23:19:56 minidsp-shd volumio[28094]: info: Loading plugin "manifestui"... Feb 24 23:19:56 minidsp-shd volumio[28094]: info: Loading plugin "metavolumio"... Feb 24 23:19:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:19:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2357. Feb 24 23:19:58 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:19:58 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:19:58 minidsp-shd go-librespot[28194]: Librespot-go daemon starting... Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=info msg="generated new device id: 5095057834e3b10f8254a0735f20f6f04f4df3fe" Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:19:58 minidsp-shd volumio[28094]: info: Loading plugin "airplay_emulation"... Feb 24 23:19:58 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:19:58 minidsp-shd volumio[28094]: info: Loading plugin "cd_controller"... Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:19:58 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:58+01:00" level=debug msg="zeroconf server listening on port 46157" Feb 24 23:19:59 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:59+01:00" level=debug msg="obtained new client token: AABKMxJSKoseVLpL9H5osjlgAG8JVm1n7BgWjRJlkUcC8gGYz3AL7leQcJxm2xofCXhYwz6Gh87zMw9radS0zqkqqutEaL6BELVcfAhQzHYE2HfA3BbR6IIzYZIeCp2jqn9eVnfs3YxN42g/z3X9CIcEA6joU95XwA311Rh+AcOxsEOFV5MrTBbRLuY/G6k+Qh1O4jBRH+HWoh9VEiE3J3r5OcJPw03i8yMSdSyUiwAFIG/D7Z677S01k6w=" Feb 24 23:19:59 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:59+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:19:59 minidsp-shd volumio[28094]: info: Loading plugin "last_100"... Feb 24 23:19:59 minidsp-shd volumio[28094]: info: Loading plugin "raat"... Feb 24 23:19:59 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:59+01:00" level=debug msg="completed keyexchange" Feb 24 23:19:59 minidsp-shd volumio[28094]: info: RAAT Plugin loaded Feb 24 23:19:59 minidsp-shd volumio[28094]: info: Adding restartRAATSocket REST API Endpoint Feb 24 23:19:59 minidsp-shd volumio[28094]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat Feb 24 23:19:59 minidsp-shd volumio[28094]: info: Loading plugin "streaming_services"... Feb 24 23:19:59 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:59+01:00" level=debug msg="completed challenge" Feb 24 23:19:59 minidsp-shd go-librespot[28194]: time="2025-02-24T23:19:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:19:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:19:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Starting Streaming Service Transparent Proxy Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "tidalconnect"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "webradio"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "i2s_dacs"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: I2S DAC not set, start Auto-detection Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "volumiodiscovery"... Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Discovery: Started advertising with name: miniDSP SHD Feb 24 23:20:01 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "calmradio"... Feb 24 23:20:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2358. Feb 24 23:20:02 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:03 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:03 minidsp-shd go-librespot[28211]: Librespot-go daemon starting... Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=info msg="generated new device id: b724edb443d51ad2eff61303bb51a18bb97b1ce8" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:03 minidsp-shd volumio[28094]: STREAMING PROXY: Starting server on port 3245 Feb 24 23:20:03 minidsp-shd volumio[28094]: Node JS runtime: 14 Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="zeroconf server listening on port 42389" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="obtained new client token: AABY/bkDzZyTLyvrgeL2ctU72mvXPUOK6G1AUUmFudB1QGKpgrAXcQ/QD35BEQQIC5TwI+jcEUk5Jt5e/T0qUiwEc+2hoQ1+BqFSg+/MUjiwif6fwBaqaRPVH0lhAl6gzbUtQHirOHOL4w54g6NNs7fyQLy71c4Mn6iys2cgh5e94FRyy4HT/ZtC8GcIDgtsMA9Q6SmHXBfcurV7NENtfzauaSk1gAoZ+90j4MYN9vdbf/ubt91dL7iZ8m/d+w==" Feb 24 23:20:03 minidsp-shd volumio[28094]: info: Loading plugin "spop"... Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:04 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:04] [connect] Successful connection Feb 24 23:20:04 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:04+01:00" level=debug msg="completed challenge" Feb 24 23:20:04 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:05 minidsp-shd volumio[28094]: info: Loading plugin "ytmusic"... Feb 24 23:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2359. Feb 24 23:20:07 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:07 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:07 minidsp-shd go-librespot[28222]: Librespot-go daemon starting... Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=info msg="generated new device id: 2eb9af6f61982933298081f319a42c720ea641f0" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="zeroconf server listening on port 41673" Feb 24 23:20:08 minidsp-shd volumio[28094]: info: Loading plugin "multiroom"... Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="obtained new client token: AAAlK279Ny7Oj4IpK+wpoe6LXjUZRZBgBtuF1XB9qrXomTBVvlBJPYSKd1FZYzZUBtR1hSR3HmZy/HXlUmKt5yF6C2cDz+vjOV65i7l9k+UjQwcKAB5AXcpTqOe421quCSgjX1XdV3ZW73UcvP1LlJyQ3inmZtr/AsyqL3BG20tUKAP+3h554ZzCm871VCNglh9K72xXmQ0MYwUUd2/zCYiK7NZvnXTMLh/9in8qay6JOC2IlXfzLojNKMs=" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="completed challenge" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin multiroom Feb 24 23:20:10 minidsp-shd sudo[28231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Feb 24 23:20:10 minidsp-shd sudo[28231]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28231]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: /bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: MultiRoom plugin initialized Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: STOPPING SNAPCLIENT Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: Snap server stop Feb 24 23:20:10 minidsp-shd sudo[28247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Feb 24 23:20:10 minidsp-shd sudo[28247]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: STOPPING volumioStreaming Feb 24 23:20:10 minidsp-shd sudo[28250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Feb 24 23:20:10 minidsp-shd sudo[28250]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28247]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd sudo[28253]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Feb 24 23:20:10 minidsp-shd sudo[28253]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "outputs"... Feb 24 23:20:10 minidsp-shd sudo[28250]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "albumart"... Feb 24 23:20:10 minidsp-shd sudo[28255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Feb 24 23:20:10 minidsp-shd sudo[28255]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28255]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd sudo[28253]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "ms_surface_dial"... Feb 24 23:20:11 minidsp-shd volumio[28094]: Forking 3 albumart workers Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin ms_surface_dial Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Plugin example_plugin is not enabled Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Loading plugin "hi_res_audio"... Feb 24 23:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2360. Feb 24 23:20:11 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:12 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:12 minidsp-shd go-librespot[28286]: Librespot-go daemon starting... Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=info msg="generated new device id: 5a18dfd181e0e8ede6ccd0b1522e94a4d86258f1" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="zeroconf server listening on port 41219" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="obtained new client token: AAA3iXuIhUcZCUfg5Uwr3Yvi4M1Dn+MAko5QqSgcv3TTzbeCBOp5azXNbkOz9kjmHegiZmliY/IIfwWZx1VTcSC5FillddGnq1cBsxBuQwcQBDTfiUQYxHTs7pYHlVI4ynVwPvio8N1Z8MT9mxJGtrdgwLGI9cwbbDVisl8XVvhiFUvnO/7Qv7RYILRBQB24+fL40dSV/aAAPHvSwE2ta/iYV9z9591FXvaxWfTPk9F8coecLpxgqUbOdmY=" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:13 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="completed challenge" Feb 24 23:20:13 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:14 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:14 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin hi_res_audio Feb 24 23:20:14 minidsp-shd volumio[28094]: info: Loading plugin "inputs"... Feb 24 23:20:16 minidsp-shd volumio[28094]: info: Loading plugin "qobuz"... Feb 24 23:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2361. Feb 24 23:20:16 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:16 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:17 minidsp-shd go-librespot[28319]: Librespot-go daemon starting... Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=info msg="generated new device id: 87aaee5f3ffa9c2283d7722b7a1f22f7096b6dfb" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="zeroconf server listening on port 46767" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="obtained new client token: AAAFDt22FQcRP24ioT2Yyaxj8UsA/8noyHPv/zgh/6gfDBjoilx6czddoZlQBr7atNi4dlHhjGTpj0XFSWIB6YFlB9EtiHW61PoYguLjdJ4gGKiXl9G2UzUpYG3wNzks9577LaN4DSiEFj+ik5FGDejxz4RVtdQcUmxAK0e6miFNJ3mL6s6uPruvkZMrFSc5RxYitsZVmADlJe9zjaiVbWR2CcFcktvltX9FdX2B7doo1V/GkZbhVVfgytV9sw==" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:18 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:18+01:00" level=debug msg="completed challenge" Feb 24 23:20:18 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:18 minidsp-shd volumio[28094]: info: Loading plugin "tidal"... Feb 24 23:20:19 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:19] [connect] Successful connection Feb 24 23:20:20 minidsp-shd volumio[28094]: info: Loading plugin "oem_helper"... Feb 24 23:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2362. Feb 24 23:20:21 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:21 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:21 minidsp-shd go-librespot[28329]: Librespot-go daemon starting... Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=info msg="generated new device id: 872c13b9bbb40c27545ffd958a123a254377dca2" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="zeroconf server listening on port 37605" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin oem_helper Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "updater_comm"... Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="obtained new client token: AAC/DEVyzDwNn6ODb2VR1W8DbcJPFrhw1s5ZubO3shYf7Z+2rQQQ6OCKBwPLQLAUeDedecIZrzNjwjST7IBGiSh1wNZyUaDHE/j9rLaqAutzp5g2cC4rduCtsNjO3fWqMjdHIMAF7WSjVTd7ePc8RDWLI0XO5zJH2oHcYHnSqk5L4D4Ps7ZNdzRi6pjIV5heTK+OhqdvaNDZSl4YLHmWVUAtgg8LaFTsZYgGObVddUm/i4h+LCD5oO2tejI=" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Plugin mpdemulation is not enabled Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "rest_api"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "websocket"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "80s80s"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin 80s80s Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="completed challenge" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: [1740435622752] [80s80s] API delay: 15 Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading i18n strings for locale it Feb 24 23:20:22 minidsp-shd volumio[28094]: Updating browse sources language Feb 24 23:20:22 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::initPlayerControls Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: Express server listening on port 3000 Feb 24 23:20:23 minidsp-shd volumio[28094]: [Metrics] WebUI: 33s 912.48ms Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::resetVolumioState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::getcurrentVolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioRetrievevolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:23 minidsp-shd sudo[28347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:20:23 minidsp-shd sudo[28347]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd sudo[28347]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Feb 24 23:20:23 minidsp-shd sudo[28350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:20:23 minidsp-shd sudo[28350]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd volumio[28094]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Completed loading Core Plugins Feb 24 23:20:23 minidsp-shd sudo[28350]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Preparing to generate the ALSA configuration file Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: Removed streaming files Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: volumioStreaming STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: SNAPSERVER STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: SNAPCLIENT STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Feb 24 23:20:23 minidsp-shd volumio[28094]: wlan0 Interface doesn't support scanning. Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Cannot use regular scanning, forcing with ap-force Feb 24 23:20:23 minidsp-shd sudo[28355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Feb 24 23:20:23 minidsp-shd sudo[28355]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd sudo[28355]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: command failed: No such device (-19) Feb 24 23:20:23 minidsp-shd volumio[28094]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Feb 24 23:20:23 minidsp-shd volumio[28094]: command failed: No such device (-19) Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Feb 24 23:20:24 minidsp-shd volumio[28094]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Reading ALSA contributions from plugins. Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 1 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 2 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 3 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 4 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 5 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 6 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 7 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Reloading queue from file Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::setRepeat false single undefined Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::setRandom null Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Setting Device type: NanoPi NEO 3 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Asound.conf file unchanged, so no further update is needed Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Output device has changed, restarting MPD Feb 24 23:20:24 minidsp-shd sudo[28365]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 24 23:20:24 minidsp-shd sudo[28365]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:24 minidsp-shd sudo[28365]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd sudo[28368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:20:25 minidsp-shd sudo[28368]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28368]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Output device has changed, restarting Shairport Sync Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd sudo[28371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:20:25 minidsp-shd sudo[28371]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd systemd[1]: Stopping Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:20:25 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: ___________ START PLUGINS ___________ Feb 24 23:20:25 minidsp-shd volumio[28094]: info: ControllerMpd::onStart: Initializing MPD Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Creating MPD Configuration file Feb 24 23:20:25 minidsp-shd sudo[28380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:20:25 minidsp-shd sudo[28380]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28380]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:25 minidsp-shd volumio[28094]: info: [1740435625373] CoreMusicLibrary::Adding element Server multimediali Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:25 minidsp-shd sudo[28383]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:20:25 minidsp-shd sudo[28383]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:20:25 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding Manifest REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding METAVOLUMIO REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd sudo[28387]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD Feb 24 23:20:25 minidsp-shd sudo[28387]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28387]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Preparing CD Folders Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding CD REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting UDEV Watcher for CD Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Detecting CD presence with UDEV Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:25 minidsp-shd volumio[28094]: info: [1740435625822] CoreMusicLibrary::Adding element Last_100 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting RAAT Plugin Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Additional UI Settings Added for plugin music_service/raat Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Streaming services startup Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting Streaming Daemon Feb 24 23:20:25 minidsp-shd sudo[28396]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 24 23:20:25 minidsp-shd sudo[28396]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2363. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:26 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:26 minidsp-shd go-librespot[28401]: Librespot-go daemon starting... Feb 24 23:20:26 minidsp-shd sudo[28396]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=info msg="generated new device id: a029fba054e96e3947e663992333a7a007db5a30" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626117] CoreMusicLibrary::Adding element Webradio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding Calm Radio to Browse Sources Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626158] CoreMusicLibrary::Adding element Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd sudo[28410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Feb 24 23:20:26 minidsp-shd sudo[28410]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Creating Spotify config file Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:26 minidsp-shd systemd[1]: Stopping Volumio Tidal Connect Service... Feb 24 23:20:26 minidsp-shd systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:26 minidsp-shd systemd[1]: vtcs.service: Succeeded. Feb 24 23:20:26 minidsp-shd systemd[1]: Stopped Volumio Tidal Connect Service. Feb 24 23:20:26 minidsp-shd sudo[28410]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626454] CoreMusicLibrary::Adding element YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Feb 24 23:20:26 minidsp-shd volumio[28094]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="zeroconf server listening on port 46833" Feb 24 23:20:26 minidsp-shd volumio[28094]: error: Hi Res Audio Failed Login: Missing Login Data Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding HIGHRESAUDIO REST API Endpoints Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Refreshing QOBUZ token Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="obtained new client token: AAAv2XSl3LU0+ZxEoFPWRPPvOgTVU3WlBcpBK+kCjaQtE5629gAj9z8ZHQ2BZOKUClM6rFTTPNNVVSBpEIokte5SBmEZ7eAfc1a7hKgHo83hSbbgjb9TOqpQ/gbZJHQstZmROTcbslJbPfGWluHsC0TNnubAtdl6tmIwBSk245DveBNUZyu3e5Xf8NJWoo9mTyAy3596GdXhSKk+B61yPYtRu3H3Q2h5bf1CwPtxZ5SuEwBpitus9tX+aWfu1Q==" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626928] CoreMusicLibrary::Adding element 80s80s Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Volumio Calling Home Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Stopping AccessToken refresher cron Feb 24 23:20:27 minidsp-shd volumio[28094]: info: AccessToken refresher cron started Feb 24 23:20:27 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:27+01:00" level=debug msg="completed challenge" Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Adding TIDAL REST API Endpoints Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Feb 24 23:20:27 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Serial port opened successfully Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot start Volumio Streaming Daemon Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 24 23:20:27 minidsp-shd volumio[28094]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' Feb 24 23:20:27 minidsp-shd volumio[28094]: Can't get device info: No such device Feb 24 23:20:27 minidsp-shd volumio[28094]: info: MPD Permissions set Feb 24 23:20:27 minidsp-shd volumio[28094]: info: MPD Permissions set Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Upmpdcli Daemon Started Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial volumioupdatevolume callback: {"vol":100,"dbVolume":0,"disableVolumeControl":false} Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Ignoring ROON Volume update because of undefined data Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} Feb 24 23:20:27 minidsp-shd volumio[28094]: info: [msSurfaceDial init()] check /org/bluez Feb 24 23:20:27 minidsp-shd volumio[28094]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::Reload Ui Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Volumio called home Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Spotify config file written Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Feb 24 23:20:27 minidsp-shd volumio[28094]: info: updateDSP function in raat called! Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Updating RAAT Signal Path Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Reconfiguring and Restarting RAAT Plugin Feb 24 23:20:27 minidsp-shd sudo[28431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 24 23:20:27 minidsp-shd sudo[28431]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:27 minidsp-shd go-librespot[28434]: Librespot-go daemon starting... Feb 24 23:20:28 minidsp-shd sudo[28431]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: Not Reporting Auto name since its the default one Feb 24 23:20:28 minidsp-shd volumio[28094]: info: RAAT Overriding default device vendor model Feb 24 23:20:28 minidsp-shd volumio[28094]: info: Adding MINIDSP Inputs Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=info msg="generated new device id: c4a446d28184256cc19dda443f0f046648db055a" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:28 minidsp-shd volumio[28094]: info: [1740435628057] CoreMusicLibrary::Adding element Inputs Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:28 minidsp-shd volumio[28094]: info: [1740435628072] CoreMusicLibrary::Adding element Presets Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:28 minidsp-shd volumio[28094]: (node:28094) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Feb 24 23:20:28 minidsp-shd volumio[28094]: (Use `node --trace-deprecation ...` to show where the warning was created) Feb 24 23:20:28 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="zeroconf server listening on port 44261" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: No need to fix Spotify hosts Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="obtained new client token: AABdQyY5ZTW40BtHKkMy3VIHq3oNVTmzmBPcgnBWUjaOP97cjDHpxUuE5cddvfiFVJMoE9RoWrIUaNB/PenfKw+bvYTcU/Sd62Al/8fr+BMu+YiE+fN2gJw0qOZvFK6sC5XlNz3aChWhLZNAMeUaU0aqN3s0rvOZlyZmHTdMAPP+E0meCNmFyRPQR2+kBJaC1leZ7HLARncVEqLkev88K2mxwEQ7zug+OJWmgbFLK4rJAgXmxMgiUJCis9I8cA==" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:28 minidsp-shd sudo[28458]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Feb 24 23:20:28 minidsp-shd sudo[28458]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:28 minidsp-shd sudo[28458]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:28 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 9 Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumiosetSourceActiveno-source Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Volumio BT Module successfully started Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd sudo[28461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28461]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:29+01:00" level=debug msg="completed challenge" Feb 24 23:20:29 minidsp-shd sudo[28464]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28464]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:20:29 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Feb 24 23:20:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd sudo[28467]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28467]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd sudo[28464]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd sudo[28461]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd volumio[28094]: xcb_connection_has_error() returned true Feb 24 23:20:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd sudo[28467]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: BQBhxErrnhkLo5hMGwQlaph0ue3bg87dLhDRB89Bl9RqH6YU9s7xpCOuHI9c4DnmF5E0FX6qWooGYBBvlriEF6RxjzbXnmsoNOOF9PFRdDR9jbBfMAkMZEaobSh-Ca8ZVGNHbGDB39Ga8_NmLgBmWJL910hCLGKT_NvmbMqMyzn5Iq7N4gU1Qs1GGZzFRmMbAprbCknYTyQ3wzsKFnfVnBESXB5v1TS1NDGiSwLjE0bkejXwpn7EHyYxuDG6uP5pGUXplFs-3jCsmAbX7XMvGxKuvw0404-M Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: New Spotify access token = BQBhxErrnhkLo5hMGwQlaph0ue3bg87dLhDRB89Bl9RqH6YU9s7xpCOuHI9c4DnmF5E0FX6qWooGYBBvlriEF6RxjzbXnmsoNOOF9PFRdDR9jbBfMAkMZEaobSh-Ca8ZVGNHbGDB39Ga8_NmLgBmWJL910hCLGKT_NvmbMqMyzn5Iq7N4gU1Qs1GGZzFRmMbAprbCknYTyQ3wzsKFnfVnBESXB5v1TS1NDGiSwLjE0bkejXwpn7EHyYxuDG6uP5pGUXplFs-3jCsmAbX7XMvGxKuvw0404-M Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 24 23:20:29 minidsp-shd sudo[28475]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Feb 24 23:20:29 minidsp-shd sudo[28475]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Feb 24 23:20:29 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:29 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd systemd[1]: Started RAAT DAEMON. Feb 24 23:20:29 minidsp-shd sudo[28475]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Access Token successfully retrieved Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:29 minidsp-shd volumio[28094]: info: [1740435629881] CoreMusicLibrary::Adding element QOBUZ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source QOBUZ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Stopping AccessToken refresher cron for QOBUZ Feb 24 23:20:30 minidsp-shd volumio[28094]: info: AccessToken refresher cron started for QOBUZ Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Adding QOBUZ REST API Endpoints Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Enabling external Volume Control Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:30 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:30 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Raat Daemon started successfully Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: Error adding Membership: Error: addMembership EINVAL Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: info: TidalConnect service stoped! Feb 24 23:20:30 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Executing endpoint restartRAATSocket Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Feb 24 23:20:30 minidsp-shd volumio[28094]: Searching all installed plugins Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: , search Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 24 23:20:30 minidsp-shd volumio[28094]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:20:30 minidsp-shd volumio[28094]: TypeError: Cannot read property 'then' of undefined Feb 24 23:20:30 minidsp-shd volumio[28094]: at ControllerMpd.search (/volumio/app/plugins/music_service/mpd/index.js:1582:17) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Feb 24 23:20:30 minidsp-shd volumio[28094]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Feb 24 23:20:30 minidsp-shd volumio[28094]: at Socket.emit (events.js:400:28) Feb 24 23:20:30 minidsp-shd volumio[28094]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 24 23:20:30 minidsp-shd volumio[28094]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Feb 24 23:20:30 minidsp-shd volumio[28094]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:20:31 minidsp-shd mpd[28386]: Feb 24 23:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 24 23:20:31 minidsp-shd systemd[1]: Started Music Player Daemon. Feb 24 23:20:31 minidsp-shd sudo[28371]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:31 minidsp-shd sudo[28383]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:31 minidsp-shd sudo[28505]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 23:19 Feb 24 23:20:31 minidsp-shd sudo[28505]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:13:25 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo3" VOLUMIO_DEVICENAME="Nanopi Neo3" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="18533ba33f8f92d7e7e459bb30f70beb"