-- Logs begin at Thu 2019-02-14 10:11:59 GMT, end at Wed 2025-03-05 18:55:27 GMT. -- Mar 05 18:54:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Mar 05 18:54:01 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:01 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:01 minidsp-shd go-librespot[2805]: Librespot-go daemon starting... Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=info msg="generated new device id: 981eaf08212dfc98d28982e15216b2563a6a53c4" Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=debug msg="stored credentials not found" Mar 05 18:54:01 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=debug msg="new websocket client" Mar 05 18:54:01 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=debug msg="obtained new client token: AAB9WL2YJSXVkGVwSI0t0g1MIdF2Z2epg/I1bUisHSJjCqEHanE+F8DAVFep9lKWpDCXk0vAWVkjAfeUvp2kezvIjODjVgD8+SBCC2Ia29eJqy7D1eptnK2m5RF3keiK19XECe2+YlmACVRQi/fVq5qemd8pko2N9DuR8ydIQTkkf0mp6GguAAsFBSoaWzwj53ahLygRD7EnhaUhbzgTPc0jYYWQeODAsx7ZoG6tgMuNWRy1rlbm8AQ1+aJm" Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:01 minidsp-shd go-librespot[2805]: time="2025-03-05T18:54:01Z" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.9:4070: connect: connection refused" Mar 05 18:54:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:01 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:54:04 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:54:04 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:04 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:54:04 minidsp-shd volumio[624]: (node:624) 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: 29) Mar 05 18:54:04 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Mar 05 18:54:04 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:04 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:04 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:54:04 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:04 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Mar 05 18:54:05 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:05 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:05 minidsp-shd go-librespot[2813]: Librespot-go daemon starting... Mar 05 18:54:05 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:05Z" level=info msg="generated new device id: c87d487d9de9022e6706975174951098550a7f5e" Mar 05 18:54:05 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:05Z" level=debug msg="stored credentials not found" Mar 05 18:54:05 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:05Z" level=debug msg="obtained new client token: AAB9jlFcoRVZbaHYRIrcbVuP0JKbx4F3H4oJCG/QbUfZr4giSk+vle3Oi1a6OctJSWxOpEFTRH7xqduNLR/ZiBcd0hk/8YJSMPCSDXlmAdV0eggGfsKDRBt1eveMvQSl5JWUiBkxxKywNqNcsCr1PouRZbw5cBDjUh882dl51QELsHD8kgkmC+o6UaJQLbRm38Q2s//vyv3TgsbKeUsaPLb754Xf16TBCJrjRXkaxP9kzqL5MlGeuk95enJf" Mar 05 18:54:05 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:05 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:05Z" level=debug msg="completed keyexchange" Mar 05 18:54:06 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:06Z" level=debug msg="completed challenge" Mar 05 18:54:06 minidsp-shd go-librespot[2813]: time="2025-03-05T18:54:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:06 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:06 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:06 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:06 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:07 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:07 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Mar 05 18:54:09 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:09 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:09 minidsp-shd go-librespot[2832]: Librespot-go daemon starting... Mar 05 18:54:09 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:09Z" level=info msg="generated new device id: 4dbfc9eab8f437c47338b915668f00d21ecb592b" Mar 05 18:54:09 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:09Z" level=debug msg="stored credentials not found" Mar 05 18:54:09 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:09Z" level=debug msg="obtained new client token: AABavX22uTZJJOrJpQkvtP788+B+JImp2NHh/Hr6ArO9fltPxDjHtnH6yuaJg66yOLL+Y+8Fv+XPwWGDYDUkmlcv19zCGzB+S0SNuH4C2DyzfYlsJOuLpbriU3zJEOZ/+32q9ScErP3qLGQvHbZQJWNvkCVL5H1tCBEXS9wijv6JGjx24zOwk7ttp1172gjCbDE8FE7DQdJoCoA//rKRrLxcNyKMtTTS2lHu4LZVjw9J573x80UYLvU36Kfh" Mar 05 18:54:09 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 18:54:10 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:10Z" level=debug msg="completed keyexchange" Mar 05 18:54:10 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:10Z" level=debug msg="completed challenge" Mar 05 18:54:10 minidsp-shd go-librespot[2832]: time="2025-03-05T18:54:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:10 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:10 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:10 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Mar 05 18:54:13 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:13 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:13 minidsp-shd go-librespot[2842]: Librespot-go daemon starting... Mar 05 18:54:13 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:13Z" level=info msg="generated new device id: 68401b038747aeb9f975ff0d7782d02b81499224" Mar 05 18:54:13 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:13Z" level=debug msg="stored credentials not found" Mar 05 18:54:13 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:13 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:13Z" level=debug msg="new websocket client" Mar 05 18:54:13 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:54:14 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:14Z" level=debug msg="obtained new client token: AACx1d7b06Oe+zHcFeBxUdjLyGxqLgOTku5VB12VqgNGNe00HptchC9g2NRq4TT5BxrrYOJZ5CMYySlLSNv63bLqPxGy8m2oOy8vdKb6G7oS3CoRm0JRs5801EdZHWf6yKcGfwUEqMBMUxUVnuELTX03mt3M03SVP+CcWQWlh9c5wdkwSuMvCyVcXkZ8qkRiLmRAxqRRxTZZc5RiJySEKx/VjeyVA9yuCxhBZ1v6QE272pudeu/KyOxWug==" Mar 05 18:54:14 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:14 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:14Z" level=debug msg="completed keyexchange" Mar 05 18:54:14 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:14Z" level=debug msg="completed challenge" Mar 05 18:54:14 minidsp-shd go-librespot[2842]: time="2025-03-05T18:54:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:14 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:54:16 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:16 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:16 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:16 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:16 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:54:16 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:16 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:54:16 minidsp-shd volumio[624]: (node:624) 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: 30) Mar 05 18:54:16 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Mar 05 18:54:17 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:17 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:17 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:54:17 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:17 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 106. Mar 05 18:54:18 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:18 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:18 minidsp-shd go-librespot[2851]: Librespot-go daemon starting... Mar 05 18:54:18 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:18Z" level=info msg="generated new device id: af2c33c2d344629dc2ae30fd8afb48d75ec76338" Mar 05 18:54:18 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:18Z" level=debug msg="stored credentials not found" Mar 05 18:54:18 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:18Z" level=debug msg="obtained new client token: AADkZ1UUG69RDOuDiQ8lk/Ar5OuZS1rMF743X+0EUPOFMxk7k11RjELDzwgY3opzNKEeIY80GkULdelNQOtqLSzqPi9R74UeM9lZ+Xr6S0pajvfrFoMoirnwssCt4UsxOt0c+hVQoGuseZmhbp14TeG0Nd58SyPiCQ2apuYTX4LFEzqWbTO1hpmFUqgXd4JF1T5XGgCezGDg7nhPFdNRySCOv1+Ilm7y+0I+0SvKm7ujPXtL+TCEf6pMo2zx" Mar 05 18:54:18 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:18Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 18:54:18 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:18Z" level=debug msg="completed keyexchange" Mar 05 18:54:19 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:19Z" level=debug msg="completed challenge" Mar 05 18:54:19 minidsp-shd go-librespot[2851]: time="2025-03-05T18:54:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:19 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:20 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:20 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 107. Mar 05 18:54:22 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:22 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:22 minidsp-shd go-librespot[2870]: Librespot-go daemon starting... Mar 05 18:54:22 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:22Z" level=info msg="generated new device id: 1a7db313f618562ff9f72e1c05dad2f9cb6793b1" Mar 05 18:54:22 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:22Z" level=debug msg="stored credentials not found" Mar 05 18:54:22 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:22Z" level=debug msg="obtained new client token: AABd0YdWWvNiFpaWrkL7vUJ4lmI7d+BTOTS77aSBOnqYITJ9h1KHwMZjVhjFmIqietDtCZd/B5ImHpdAT/vvwEg3HaqTFEmT3VXYOt8hrrWhzGt/EMyf/35pQpU9hAt4iRwNpGPfvfiOVf0wTIcPqFSn7Dow9WSclgV5LA+NzkIUvFmo0BToY1aDR1bCCSytLLOoCIKvrZ8A/luJ7q3MH6vxhIRMhl8nibHzoAKcSwAbOVfJRijLeyUUJRc2" Mar 05 18:54:22 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:22 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:22Z" level=debug msg="completed keyexchange" Mar 05 18:54:23 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:23Z" level=debug msg="completed challenge" Mar 05 18:54:23 minidsp-shd go-librespot[2870]: time="2025-03-05T18:54:23Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:23 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:23 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:26 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:26 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:26 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:26 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:26 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:26 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 108. Mar 05 18:54:26 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:26 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:26 minidsp-shd go-librespot[2878]: Librespot-go daemon starting... Mar 05 18:54:26 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:26Z" level=info msg="generated new device id: 2c307bda23a5c14ca6dbb1f97c8b396b7f827daa" Mar 05 18:54:26 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:26Z" level=debug msg="stored credentials not found" Mar 05 18:54:26 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:27 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:27Z" level=debug msg="new websocket client" Mar 05 18:54:27 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:54:27 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:27Z" level=debug msg="obtained new client token: AACP277JEwIFic1Je6XgbwqZiMrZL6OCdpl6BWhukv8R2x+y5mfCEtaJynQ0q2xjjRpM6lH8wjW7PqNplpEsB9sjv8c3nwfzgGloWiO5OpCt2cJnTJIkS/1MyAYLk69NmpH3BzP2pdRmVCOhmWlVzzzxB6uDT4qQnQN6YfGXpFfvMMaESZ92b2i5iHVzjlixRrsBopDzQ4LHF1OjaKEt/4k6WwNPoig4AWmHmhNvKkXtx53V/DR9Kls6Cg==" Mar 05 18:54:27 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:27Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:27 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:27Z" level=debug msg="completed keyexchange" Mar 05 18:54:27 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:27Z" level=debug msg="completed challenge" Mar 05 18:54:28 minidsp-shd go-librespot[2878]: time="2025-03-05T18:54:28Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:28 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:54:30 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:54:30 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:30 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:54:30 minidsp-shd volumio[624]: (node:624) 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: 31) Mar 05 18:54:30 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Mar 05 18:54:30 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:30 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:30 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:54:31 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:31 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 109. Mar 05 18:54:31 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:31 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:31 minidsp-shd go-librespot[2897]: Librespot-go daemon starting... Mar 05 18:54:31 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:31Z" level=info msg="generated new device id: 41428eca4ab941c6b2965f81cb254aa95b48e6a4" Mar 05 18:54:31 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:31Z" level=debug msg="stored credentials not found" Mar 05 18:54:31 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:31Z" level=debug msg="obtained new client token: AAChoYXcX4cKRWvVoV0dbvI1759FihfBaZtXOwtkpH080io2P0FNAB0Z3f8NB8lrw1EO7IEXWPjGmedGDvmaHJvTygJ4kTXQKGE16qIn053rplVtFJahX7iWKVo+TEcdsdMwptiS1y/pKn/64QRKzu9DLkkdoqFUHKWmlGqIHcLgr1FdxV1lSrpdMWNY0HRT8LHIDlgFOxFLDixJtFE3oWwwxMgMEdHXXCVBdghx958Ve9ucYAVgodA5nX0W" Mar 05 18:54:31 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:31Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:31 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:31Z" level=debug msg="completed keyexchange" Mar 05 18:54:32 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:32Z" level=debug msg="completed challenge" Mar 05 18:54:32 minidsp-shd go-librespot[2897]: time="2025-03-05T18:54:32Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:34 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:34 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:35 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 110. Mar 05 18:54:35 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:35 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:35 minidsp-shd go-librespot[2907]: Librespot-go daemon starting... Mar 05 18:54:35 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:35Z" level=info msg="generated new device id: d7c4a35df41412ec76f1bcc024167a8fcb1c0353" Mar 05 18:54:35 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:35Z" level=debug msg="stored credentials not found" Mar 05 18:54:35 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:35Z" level=debug msg="obtained new client token: AADFm5op4nz+W507fLoD6GVJ5pMJZEHRKTbh17dadvZcaHYWs9fdwwCBbXeSth1VgZtJSDSKkKW2Mb2HrOGdjLXkZLMbMSlAk1HfLYlUNYnlznSqmbcoXaEqP6zuGfaM0NikG1IdcGv5aIcWo0z1uvHo8JrTCTjSkB9K/i23zB2vsLMUcI8wYOKjWSpTMGE2QGvv85sJ4QOa/L5Jaa7rolmnQ+eSc/scLEFR6ugOcpRFAC+surQtE9zPI5tG" Mar 05 18:54:36 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:36Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:36 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:36Z" level=debug msg="completed keyexchange" Mar 05 18:54:36 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:36 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:36 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:36 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:36 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:36 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:36 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:36 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:36 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:36Z" level=debug msg="completed challenge" Mar 05 18:54:36 minidsp-shd go-librespot[2907]: time="2025-03-05T18:54:36Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:37 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:37 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 111. Mar 05 18:54:40 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:40 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:40 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:40 minidsp-shd go-librespot[2927]: Librespot-go daemon starting... Mar 05 18:54:40 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:40 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:40Z" level=info msg="generated new device id: e557714bdf57511d90d335c12cbec663c322ff44" Mar 05 18:54:40 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:40Z" level=debug msg="stored credentials not found" Mar 05 18:54:40 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:40Z" level=debug msg="obtained new client token: AAAOADj96aTseA1ZELoI51F/Y3uN4q2Z2k/TciD3FSIoGYYTajbw4wAyZQKiK4w3E//r6P1fz5YfY+9ipipV5EOGS1QqN7HnJ5QvH2E+QZ+6Q3rRgQ/m98YgTzcguEi4CVopEM96+ykxjDO5KRMF6nKU19aCIiHiAhyl5n7Wc3My6+N654xiDwFiXVNOuzTD2FJCRTK1rdOS0/JCikKLrXGgydgS/pmVQ6apYa2BxCr9CrrAHqOW7ipQMH4a" Mar 05 18:54:40 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:40Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:40 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:40Z" level=debug msg="completed keyexchange" Mar 05 18:54:41 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:41Z" level=debug msg="completed challenge" Mar 05 18:54:41 minidsp-shd go-librespot[2927]: time="2025-03-05T18:54:41Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:43 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:43 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:44 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:44 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 112. Mar 05 18:54:44 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:44 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:44 minidsp-shd go-librespot[2936]: Librespot-go daemon starting... Mar 05 18:54:44 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:44Z" level=info msg="generated new device id: b9d004f78a91f17f8f65d48cfcec412573f544d9" Mar 05 18:54:44 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:44Z" level=debug msg="stored credentials not found" Mar 05 18:54:44 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:44Z" level=debug msg="obtained new client token: AABY7M7DJXiZQs4tKmj9uLgC2P7qO9JFzEMPM/CFQdVMrS8HySqxwfttX/CNnafckScJaQQ8cHZqW5rhO/ZTE2VmVe16mKBx9SMJFkmyp0PEvh762g9c+9YxyEJA2TvQzYfyqzi6QEiLqSRM4WgwoinqqtdOecjID8QyU5IB5FpemGnwzarE+E6vIGY01i5rv4I3NAYXJLDyH58z89Gel14iB7TBwacL6OXlFgsAftL4naY4L89MIxxW9SmY" Mar 05 18:54:44 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:44Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:44 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:44Z" level=debug msg="completed keyexchange" Mar 05 18:54:45 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:45Z" level=debug msg="completed challenge" Mar 05 18:54:45 minidsp-shd go-librespot[2936]: time="2025-03-05T18:54:45Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:46 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:46 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:46 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:46 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:46 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:46 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:48 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:48 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 113. Mar 05 18:54:48 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:48 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:48 minidsp-shd go-librespot[2983]: Librespot-go daemon starting... Mar 05 18:54:48 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:48Z" level=info msg="generated new device id: 985a470e2b5c959bcb5a0ab90a94a5ca78387df5" Mar 05 18:54:48 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:48Z" level=debug msg="stored credentials not found" Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=debug msg="obtained new client token: AAC9j5GC9F0lm4mrbVCVS4j2xLxeeucjb0cjtdf0wu4fOFF/mtgtTrmDFl8fgoznF3IxGuSpEQ3o3jr277KNrUMOAgeUYYyTrpwpUMslADYyedzzmsToal9kcmbM+G4as/5YNZ7IXtD3kjsBG378b2D4qupL0/MHm/SgKUawrxzTgMRhm2d6ACRI+Ho9JgSIhEWohUGE9rraelTxJe18BJuuad1byflgkJwXnoEcsK7PoaO8+bHcTodetxdM" Mar 05 18:54:49 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=debug msg="new websocket client" Mar 05 18:54:49 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=debug msg="completed keyexchange" Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=debug msg="completed challenge" Mar 05 18:54:49 minidsp-shd go-librespot[2983]: time="2025-03-05T18:54:49Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:49 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:49 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 18:54:51 minidsp-shd volumio[624]: info: Discovery: Getting this device information Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:51 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 18:54:51 minidsp-shd volumio[624]: verbose: New Socket.io Connection to 192.168.50.239:3000 from 192.168.50.177 UA: Dart/3.5 (dart:io) Total Clients: 7 Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:51 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 05 18:54:51 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 05 18:54:52 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:54:52 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:52 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:54:52 minidsp-shd volumio[624]: (node:624) 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: 32) Mar 05 18:54:52 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Mar 05 18:54:52 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:52 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:52 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:54:52 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:52 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 114. Mar 05 18:54:53 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:53 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:53 minidsp-shd go-librespot[3003]: Librespot-go daemon starting... Mar 05 18:54:53 minidsp-shd go-librespot[3003]: time="2025-03-05T18:54:53Z" level=info msg="generated new device id: a0c62c930306b883750ef0bcfdc18f6781dab3c9" Mar 05 18:54:53 minidsp-shd go-librespot[3003]: time="2025-03-05T18:54:53Z" level=debug msg="stored credentials not found" Mar 05 18:54:53 minidsp-shd go-librespot[3003]: time="2025-03-05T18:54:53Z" level=debug msg="obtained new client token: AABjAx30s8naHHWy9KetD08GwbLNZpIDrp5zAl6zjcvbiEFt0yz5LO3HvNjipR3Mzzj9TsVIrtLjryD4IwSyK64oMWZtY4XXrqCMF6DwIstazFLRId62GYIY0VgbF1QRar14FLi7AD9nT/bgUFsGNtbH3WJSR79s4NBRkdzkGj74g3H5NzqZdXTL7LUreLHTdjfgDtQG4aDSsbAZg95AeUwsfc0dJtMdkyNA9bRpn3X1pySZMJKwttyB8/uU" Mar 05 18:54:53 minidsp-shd go-librespot[3003]: time="2025-03-05T18:54:53Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:53 minidsp-shd go-librespot[3003]: time="2025-03-05T18:54:53Z" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.9:4070: connect: connection refused" Mar 05 18:54:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:53 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:55 minidsp-shd sudo[3013]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 18:54:55 minidsp-shd sudo[3013]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 18:54:55 minidsp-shd sudo[3013]: pam_unix(sudo:session): session closed for user root Mar 05 18:54:55 minidsp-shd sudo[3016]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 18:54:55 minidsp-shd sudo[3016]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 18:54:55 minidsp-shd sudo[3016]: pam_unix(sudo:session): session closed for user root Mar 05 18:54:55 minidsp-shd volumio[624]: verbose: New Socket.io Connection to 192.168.50.239 from 192.168.50.177 UA: Mozilla/5.0 (Linux; Android 15; FCP-N49 Build/HONORFCP-N49; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Safari/537.36 Total Clients: 8 Mar 05 18:54:55 minidsp-shd sudo[3021]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 18:54:55 minidsp-shd sudo[3021]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 18:54:55 minidsp-shd sudo[3021]: pam_unix(sudo:session): session closed for user root Mar 05 18:54:55 minidsp-shd sudo[3024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 18:54:55 minidsp-shd sudo[3024]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 18:54:55 minidsp-shd sudo[3024]: pam_unix(sudo:session): session closed for user root Mar 05 18:54:55 minidsp-shd volumio[624]: verbose: New Socket.io Connection to 192.168.50.239 from 192.168.50.177 UA: Mozilla/5.0 (Linux; Android 15; FCP-N49 Build/HONORFCP-N49; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Safari/537.36 Total Clients: 9 Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetVisibleSources Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:55 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 05 18:54:55 minidsp-shd volumio[624]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Mar 05 18:54:55 minidsp-shd volumio[624]: info: Received Get System Info Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 18:54:55 minidsp-shd volumio[624]: info: Discovery: Getting this device information Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:55 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:55 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:55 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 05 18:54:55 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 05 18:54:55 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:55 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:56 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 05 18:54:56 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:56 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:56 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:56 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:56 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:56 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:56 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:56 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:54:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:54:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 115. Mar 05 18:54:56 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:54:56 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:54:56 minidsp-shd go-librespot[3028]: Librespot-go daemon starting... Mar 05 18:54:56 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:56Z" level=info msg="generated new device id: ba3240aa0b5beee21d5a2cf4ae1f740db409558c" Mar 05 18:54:56 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:56Z" level=debug msg="stored credentials not found" Mar 05 18:54:57 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:57Z" level=debug msg="obtained new client token: AAANMPI5SGcrl+NmEiMwIDA7KBcbnokXzBklXzs3bXIRXFCFHxjFk2/3cMxh/uK5rCpCIzxrWGk2GdgY/eDUFaAR2Yn5Q/FqonZxSGslwNyyI9Eay9lBGP6mBf2QDauY4auUu9bXswLpv+4ssyw8OFPCHBombP1YrntdMjAxUQ8LJqaltrK61T8U2V6ZjwgSH4NcKU3KpKQ46ATp1eXmFmAItq/IoCwlHqRE0d5oinYZOfy3F0UFq/XDPw==" Mar 05 18:54:57 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:57Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:54:57 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:57Z" level=debug msg="completed keyexchange" Mar 05 18:54:57 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 05 18:54:57 minidsp-shd volumio[624]: info: Received Get System Info Mar 05 18:54:57 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 18:54:57 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 18:54:57 minidsp-shd volumio[624]: info: Discovery: Getting this device information Mar 05 18:54:57 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:57 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:57 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 18:54:57 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:57Z" level=debug msg="completed challenge" Mar 05 18:54:58 minidsp-shd go-librespot[3028]: time="2025-03-05T18:54:58Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:54:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:54:58 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:54:58 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:54:58 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:54:59 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 05 18:54:59 minidsp-shd volumio[624]: info: Received Get System Info Mar 05 18:54:59 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 18:54:59 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 18:54:59 minidsp-shd volumio[624]: info: Discovery: Getting this device information Mar 05 18:54:59 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:54:59 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:54:59 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 18:55:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:01 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 116. Mar 05 18:55:01 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:01 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:01 minidsp-shd go-librespot[3048]: Librespot-go daemon starting... Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=info msg="generated new device id: c717a9cdf52d329319b3a2630d6e5831a0ba4ef5" Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=debug msg="stored credentials not found" Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=debug msg="obtained new client token: AAD+1j9J7CXhQx9iSle/uydlSk8xK5TCtmKqNSWUPWFR4Tn9Zh+wtjZiqNKQTUMuaIEy2XvCTVCyMcky1e/KhAfpq+uXZU6uOqomKcJTIiXGrCiVDC/fpv696DJXt4y3ljZ0z8yYh0wm7ugoBOY8bDdipXF2sZ6eawd4vYVbxWSIv1BNsXkGUyUkzG4S7VCkU2vl8x0KtoQ52wClZMsl4G+JfRyv7V8jaclKgbWTNKZIukYSzIdfLW8zdTLw" Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=debug msg="completed keyexchange" Mar 05 18:55:01 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:01 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:01Z" level=debug msg="new websocket client" Mar 05 18:55:01 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:55:02 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:02Z" level=debug msg="completed challenge" Mar 05 18:55:02 minidsp-shd go-librespot[3048]: time="2025-03-05T18:55:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:02 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:55:04 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:55:04 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:04 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:55:04 minidsp-shd volumio[624]: (node:624) 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: 33) Mar 05 18:55:05 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Mar 05 18:55:05 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:05 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:05 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:05 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:05 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 117. Mar 05 18:55:05 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:05 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:05 minidsp-shd go-librespot[3058]: Librespot-go daemon starting... Mar 05 18:55:05 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:05Z" level=info msg="generated new device id: db41681f008994b711ef6db51d0f00b3078f5fc7" Mar 05 18:55:05 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:05Z" level=debug msg="stored credentials not found" Mar 05 18:55:05 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:05Z" level=debug msg="obtained new client token: AAC8IURS1J/WEqC9QQRvyDdISqbojN9Z+Z2Rhqm6+6GisH7b1aKEUHWkzA0tLGBKMtywwcmPRECrnZ8uwDUGeH+4Fk3KMMeZfkaZ66j5nM4YwqR54FpaVwh5pHlX/z/Asy8Whm8Su9Dr4l+17FH4yP9+EiVNPLwBw5RXHYHvhvmvNFLpCOA8qhvf644MkvF7EUwZ9tmJVQgEkl2P2ns07aFXSEcQwipl4CZuQEI+QGttwMhHKf/q6GbgKJa8" Mar 05 18:55:06 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:06Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:06 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:06Z" level=debug msg="completed keyexchange" Mar 05 18:55:06 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:06 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:06 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:06 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:06 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:06Z" level=debug msg="completed challenge" Mar 05 18:55:06 minidsp-shd go-librespot[3058]: time="2025-03-05T18:55:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:06 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:08 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:08 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 118. Mar 05 18:55:09 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:09 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:09 minidsp-shd go-librespot[3077]: Librespot-go daemon starting... Mar 05 18:55:09 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:09Z" level=info msg="generated new device id: 08800451e24ed15a108fc0b802ee36610e0c8e9b" Mar 05 18:55:09 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:09Z" level=debug msg="stored credentials not found" Mar 05 18:55:10 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:10Z" level=debug msg="obtained new client token: AABUrwnUxReVYJyy5gqjZjylchlNcnHDFfYvqngetXmTN4IuvDD7Vy7b6A1MN9QJhRgI/BXYKp7CnmWEfM0nSMGiVeel9kg5FnZP6a2VF6XWK1QGo/YYnL3Zh9q807yF36J+GtY43ag+bXSnDeihHeQYAiq1IHuE/bIcIVhVp/hL+GCIF4ReMjgIzQOTAGTiSEMn+1VzOuWscr+jWIfKY4IkmbTFhCmaShTFBXEISvB1AcEaOhshCjVDjQ==" Mar 05 18:55:10 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:10Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:10 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:10Z" level=debug msg="completed keyexchange" Mar 05 18:55:11 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:11Z" level=debug msg="completed challenge" Mar 05 18:55:11 minidsp-shd go-librespot[3077]: time="2025-03-05T18:55:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:11 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:11 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 119. Mar 05 18:55:14 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:14 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:14 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:14 minidsp-shd go-librespot[3087]: Librespot-go daemon starting... Mar 05 18:55:14 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:14 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:14Z" level=info msg="generated new device id: a21794029b2264d8a030d7d2fae212a5528b5239" Mar 05 18:55:14 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:14Z" level=debug msg="stored credentials not found" Mar 05 18:55:14 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:14Z" level=debug msg="obtained new client token: AACic3eDKwgPktJZ32rKvu8GpkVAH9aAeFWK0ro1ixvM2cmYHwdXvOROxWcnEhkpBS2GVTIwGyq/3zbIwFht2t5KWyqguqdlEZU5L4wf6MCGwZrj4VWyysEyPpzpLR8J0nDMTSxr4rNN4f0nItSCJ/DpOr53jfod1NrH+rRlOQsICRzMGkXPeGCvAgtGHIlWczFuIpjwCdzys3tF71446bXHIEQKsMeAgSRcgu8FP5UuCzYNw9Fc5q9AIEdC" Mar 05 18:55:14 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:14 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:14Z" level=debug msg="completed keyexchange" Mar 05 18:55:15 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:15Z" level=debug msg="completed challenge" Mar 05 18:55:15 minidsp-shd go-librespot[3087]: time="2025-03-05T18:55:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:16 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:16 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:55:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:55:16 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:16 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:55:16 minidsp-shd volumio[624]: info: Listing playlists Mar 05 18:55:17 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:17 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 120. Mar 05 18:55:18 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:18 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:18 minidsp-shd go-librespot[3101]: Librespot-go daemon starting... Mar 05 18:55:18 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:18Z" level=info msg="generated new device id: f4e99d08b4ca9f361b6eda444d14ab4cc8dc766e" Mar 05 18:55:18 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:18Z" level=debug msg="stored credentials not found" Mar 05 18:55:18 minidsp-shd volumio[624]: info: Clearing queue after UPNP request Mar 05 18:55:19 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:19Z" level=debug msg="obtained new client token: AAAOL2+u9f35tGf9uK8ceuPjitpkeZjVVwgDPNWWRmxRAyRgeuEMSX+lSLGGBnEE9HSOubtg6JxgBzYMmnO5lgDuSMNxqH8dh8m0vRDUEMOW83kLQEO3EhZrdQR8eYvpqV9BUWyj63NvTPiEj3L///Gdlzo+75uZu7dZBVbyM5Jo4X5EYg3Oh+m2SKtaN95LFfhvoDbkHGbYTMq644cmTqPPhT2FMrAK3frsZTIIcJ257Zdkts2XwAF02w==" Mar 05 18:55:19 minidsp-shd volumio[624]: info: CoreStateMachine::ClearQueue Mar 05 18:55:19 minidsp-shd volumio[624]: info: CoreStateMachine::stop Mar 05 18:55:19 minidsp-shd volumio[624]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 05 18:55:19 minidsp-shd volumio[624]: info: CorePlayQueue::clearPlayQueue Mar 05 18:55:19 minidsp-shd volumio[624]: info: CorePlayQueue::saveQueue Mar 05 18:55:19 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushState Mar 05 18:55:19 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output update for this device Mar 05 18:55:19 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output Mar 05 18:55:19 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushQueue Mar 05 18:55:19 minidsp-shd volumio[624]: error: Upnp client error: Error: This socket has been ended by the other party Mar 05 18:55:19 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:19 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:19 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:19Z" level=debug msg="completed keyexchange" Mar 05 18:55:19 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:19Z" level=debug msg="completed challenge" Mar 05 18:55:19 minidsp-shd go-librespot[3101]: time="2025-03-05T18:55:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:20 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:20 minidsp-shd volumio[624]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:20 minidsp-shd volumio[624]: info: Starting UPNP Playback Mar 05 18:55:20 minidsp-shd volumio[624]: info: Preparing playback through UPNP Mar 05 18:55:20 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:20 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:20 minidsp-shd volumio[624]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 33ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 24ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 20ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 16ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 12ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 9ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 10ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 6ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 9ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 11ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 13ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 11ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 17ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 12ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 9ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Mar 05 18:55:21 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:21 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 17ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 14ms Mar 05 18:55:21 minidsp-shd volumio[624]: info: ------------------------------ 11ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 36 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 32 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 21 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 43 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 35 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 27 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 26 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 20 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 17 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Music Assistant","artist":null,"album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus stop Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Music Assistant","artist":null,"album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output update for this device Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output update for this device Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Music Assistant","artist":null,"album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output update for this device Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioPushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output update for this device Mar 05 18:55:22 minidsp-shd volumio[624]: info: MRS: Pushing multiroomSync output Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 243ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 264ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 260ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 193 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 186 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 186 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 314ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 274ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 269ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces system playlist update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Ignoring MPD Status Update Mar 05 18:55:22 minidsp-shd volumio[624]: info: Mar 05 18:55:22 minidsp-shd volumio[624]: ---------------------------- MPD announces state update: player Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::getState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand status Mar 05 18:55:22 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 129ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 124 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 69ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 66 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 64ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand status took 60 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 36 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 34 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: info: sendMpdCommand playlistinfo took 34 milliseconds Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: ControllerMpd::parseTrackInfo Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":934,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"3588 Kbps","isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1021,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"3623 Kbps","isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: ControllerMpd::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::servicePushState Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: In UPNP mode Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1021,"duration":0,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"3877 Kbps","isStreaming":false,"title":"2d8836d2d8e8465587829386a5d979a7.flac","artist":"Music Assistant","album":null,"uri":"http://192.168.50.162:8097/flow/uuid:fbbfb509-4367-98cd-f915-768181137e82/2d8836d2d8e8465587829386a5d979a7.flac","trackType":"flac"} Mar 05 18:55:22 minidsp-shd volumio[624]: verbose: CURRENT POSITION 0 Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState stateService play Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::syncState currentStatus play Mar 05 18:55:22 minidsp-shd volumio[624]: info: Received an update from plugin. extracting info from payload Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreStateMachine::pushState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 220ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 161ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: ------------------------------ 153ms Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Mar 05 18:55:22 minidsp-shd volumio[624]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Mar 05 18:55:22 minidsp-shd volumio[624]: at ControllerYTCR.isCurrentService (/data/plugins/music_service/ytcr/dist/index.js:468:95) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer. (/data/plugins/music_service/ytcr/dist/index.js:285:22) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer.emit (events.js:412:35) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer._Player_setStatusAndEmit (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/Player.js:334:10) Mar 05 18:55:22 minidsp-shd volumio[624]: at runMicrotasks () Mar 05 18:55:22 minidsp-shd volumio[624]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Mar 05 18:55:22 minidsp-shd volumio[624]: at async MPDPlayer._MPDPlayer_handleExternalMPDEvent (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:565:9) Mar 05 18:55:22 minidsp-shd volumio[624]: at async MPDSubsystemEventEmitter._MPDSubsystemEventEmitter_handleSystemEvent (/data/plugins/music_service/ytcr/dist/lib/MPDSubsystemEventEmitter.js:135:21) Mar 05 18:55:22 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 34) Mar 05 18:55:22 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:22 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:22 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:22 minidsp-shd volumio[624]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Mar 05 18:55:22 minidsp-shd volumio[624]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Mar 05 18:55:22 minidsp-shd volumio[624]: at ControllerYTCR.isCurrentService (/data/plugins/music_service/ytcr/dist/index.js:468:95) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer. (/data/plugins/music_service/ytcr/dist/index.js:285:22) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer.emit (events.js:412:35) Mar 05 18:55:22 minidsp-shd volumio[624]: at MPDPlayer._Player_setStatusAndEmit (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/Player.js:334:10) Mar 05 18:55:22 minidsp-shd volumio[624]: at runMicrotasks () Mar 05 18:55:22 minidsp-shd volumio[624]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Mar 05 18:55:22 minidsp-shd volumio[624]: at async MPDPlayer._MPDPlayer_handleExternalMPDEvent (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:565:9) Mar 05 18:55:22 minidsp-shd volumio[624]: at async MPDSubsystemEventEmitter._MPDSubsystemEventEmitter_handleSystemEvent (/data/plugins/music_service/ytcr/dist/lib/MPDSubsystemEventEmitter.js:135:21) Mar 05 18:55:22 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 35) Mar 05 18:55:22 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:22 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:22 minidsp-shd volumio[624]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 05 18:55:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 121. Mar 05 18:55:23 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:23 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:23 minidsp-shd go-librespot[3131]: Librespot-go daemon starting... Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=info msg="generated new device id: 17bf9a27c9cce37436e1e9fe24c1b783017f4df4" Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=debug msg="stored credentials not found" Mar 05 18:55:23 minidsp-shd volumio[624]: info: Initializing connection to go-librespot Websocket Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=debug msg="new websocket client" Mar 05 18:55:23 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=debug msg="obtained new client token: AAC3cVmd1/kLCV1Nf/T1y7FvPD6Atiwa+Z3MR5KvUl4golWCFnO0HTu2dBQxaM0pgrAwubaACaNlKdzq/+Jh94VhsR6V/vu1euAPn7TmTQ1NlPrhYUM+p+eEHoclMr45hVjAUzEppdbCnPbSwa39ZdQ/2y1iJ/iOtuZjxvrWdBFmnEOVOUn+kvs1hFjeCzHq3R8izIVkE/YTzxZSnG4Wbp8zPCf6HvIAstwaHXhds/xmyK5BFpwGhHLlPFHj" Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 18:55:23 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:23Z" level=debug msg="completed keyexchange" Mar 05 18:55:24 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:24Z" level=debug msg="completed challenge" Mar 05 18:55:24 minidsp-shd go-librespot[3131]: time="2025-03-05T18:55:24Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Mar 05 18:55:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 18:55:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 18:55:24 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket closed Mar 05 18:55:26 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:26 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:26 minidsp-shd volumio[624]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Mar 05 18:55:26 minidsp-shd volumio[624]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Mar 05 18:55:26 minidsp-shd volumio[624]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at /volumio/node_modules/express/lib/router/index.js:281:22 Mar 05 18:55:26 minidsp-shd volumio[624]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Mar 05 18:55:26 minidsp-shd volumio[624]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Mar 05 18:55:26 minidsp-shd volumio[624]: at /volumio/node_modules/express/lib/router/index.js:284:7 Mar 05 18:55:26 minidsp-shd volumio[624]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Mar 05 18:55:26 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:26 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:26 minidsp-shd volumio[624]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Mar 05 18:55:26 minidsp-shd volumio[624]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Mar 05 18:55:26 minidsp-shd volumio[624]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at /volumio/node_modules/express/lib/router/index.js:281:22 Mar 05 18:55:26 minidsp-shd volumio[624]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Mar 05 18:55:26 minidsp-shd volumio[624]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Mar 05 18:55:26 minidsp-shd volumio[624]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Mar 05 18:55:26 minidsp-shd volumio[624]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Mar 05 18:55:26 minidsp-shd volumio[624]: at /volumio/node_modules/express/lib/router/index.js:284:7 Mar 05 18:55:26 minidsp-shd volumio[624]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Mar 05 18:55:26 minidsp-shd volumio[624]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Mar 05 18:55:26 minidsp-shd volumio[624]: info: Getting Spotify volume Mar 05 18:55:26 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 18:55:26 minidsp-shd volumio[624]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Mar 05 18:55:26 minidsp-shd volumio[624]: (node:624) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 36) Mar 05 18:55:26 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Mar 05 18:55:26 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Mar 05 18:55:26 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Mar 05 18:55:26 minidsp-shd volumio[624]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 18:55:26 minidsp-shd volumio[624]: TypeError: Cannot read property 'name' of undefined Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Mar 05 18:55:26 minidsp-shd volumio[624]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Mar 05 18:55:26 minidsp-shd volumio[624]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:53:38) Mar 05 18:55:26 minidsp-shd volumio[624]: at Socket.emit (events.js:400:28) Mar 05 18:55:26 minidsp-shd volumio[624]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Mar 05 18:55:26 minidsp-shd volumio[624]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Mar 05 18:55:26 minidsp-shd volumio[624]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 18:55:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 05 18:55:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 122. Mar 05 18:55:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Mar 05 18:55:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Mar 05 18:55:27 minidsp-shd go-librespot[3156]: Librespot-go daemon starting... Mar 05 18:55:27 minidsp-shd sudo[3155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-05 18:54 Mar 05 18:55:27 minidsp-shd sudo[3155]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 18:55:27 minidsp-shd go-librespot[3156]: time="2025-03-05T18:55:27Z" level=info msg="generated new device id: 48af479b5f1a5c7b623f6dca112740b1be12eb5f" Mar 05 18:55:27 minidsp-shd go-librespot[3156]: time="2025-03-05T18:55:27Z" level=debug msg="stored credentials not found" 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"