-- Logs begin at Mon 2025-02-24 21:39:00 CET, end at Mon 2025-02-24 23:21:44 CET. -- Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Starting Streaming Service Transparent Proxy Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "tidalconnect"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "webradio"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "i2s_dacs"... Feb 24 23:20:01 minidsp-shd volumio[28094]: info: I2S DAC not set, start Auto-detection Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "volumiodiscovery"... Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd volumio[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:01 minidsp-shd node[28094]: *** WARNING *** For more information see Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Discovery: Started advertising with name: miniDSP SHD Feb 24 23:20:01 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:01 minidsp-shd volumio[28094]: info: Loading plugin "calmradio"... Feb 24 23:20:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:02 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2358. Feb 24 23:20:02 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:03 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:03 minidsp-shd go-librespot[28211]: Librespot-go daemon starting... Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=info msg="generated new device id: b724edb443d51ad2eff61303bb51a18bb97b1ce8" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:03 minidsp-shd volumio[28094]: STREAMING PROXY: Starting server on port 3245 Feb 24 23:20:03 minidsp-shd volumio[28094]: Node JS runtime: 14 Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="zeroconf server listening on port 42389" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="obtained new client token: AABY/bkDzZyTLyvrgeL2ctU72mvXPUOK6G1AUUmFudB1QGKpgrAXcQ/QD35BEQQIC5TwI+jcEUk5Jt5e/T0qUiwEc+2hoQ1+BqFSg+/MUjiwif6fwBaqaRPVH0lhAl6gzbUtQHirOHOL4w54g6NNs7fyQLy71c4Mn6iys2cgh5e94FRyy4HT/ZtC8GcIDgtsMA9Q6SmHXBfcurV7NENtfzauaSk1gAoZ+90j4MYN9vdbf/ubt91dL7iZ8m/d+w==" Feb 24 23:20:03 minidsp-shd volumio[28094]: info: Loading plugin "spop"... Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:03 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:03+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:04 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:04] [connect] Successful connection Feb 24 23:20:04 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:04+01:00" level=debug msg="completed challenge" Feb 24 23:20:04 minidsp-shd go-librespot[28211]: time="2025-02-24T23:20:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:04 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:05 minidsp-shd volumio[28094]: info: Loading plugin "ytmusic"... Feb 24 23:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:07 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2359. Feb 24 23:20:07 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:07 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:07 minidsp-shd go-librespot[28222]: Librespot-go daemon starting... Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=info msg="generated new device id: 2eb9af6f61982933298081f319a42c720ea641f0" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:07 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:07+01:00" level=debug msg="zeroconf server listening on port 41673" Feb 24 23:20:08 minidsp-shd volumio[28094]: info: Loading plugin "multiroom"... Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="obtained new client token: AAAlK279Ny7Oj4IpK+wpoe6LXjUZRZBgBtuF1XB9qrXomTBVvlBJPYSKd1FZYzZUBtR1hSR3HmZy/HXlUmKt5yF6C2cDz+vjOV65i7l9k+UjQwcKAB5AXcpTqOe421quCSgjX1XdV3ZW73UcvP1LlJyQ3inmZtr/AsyqL3BG20tUKAP+3h554ZzCm871VCNglh9K72xXmQ0MYwUUd2/zCYiK7NZvnXTMLh/9in8qay6JOC2IlXfzLojNKMs=" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=debug msg="completed challenge" Feb 24 23:20:08 minidsp-shd go-librespot[28222]: time="2025-02-24T23:20:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin multiroom Feb 24 23:20:10 minidsp-shd sudo[28231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Feb 24 23:20:10 minidsp-shd sudo[28231]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28231]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: /bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: MultiRoom plugin initialized Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: STOPPING SNAPCLIENT Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: Snap server stop Feb 24 23:20:10 minidsp-shd sudo[28247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Feb 24 23:20:10 minidsp-shd sudo[28247]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd volumio[28094]: info: MRS: STOPPING volumioStreaming Feb 24 23:20:10 minidsp-shd sudo[28250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Feb 24 23:20:10 minidsp-shd sudo[28250]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28247]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd sudo[28253]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Feb 24 23:20:10 minidsp-shd sudo[28253]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "outputs"... Feb 24 23:20:10 minidsp-shd sudo[28250]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "albumart"... Feb 24 23:20:10 minidsp-shd sudo[28255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Feb 24 23:20:10 minidsp-shd sudo[28255]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:10 minidsp-shd sudo[28255]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd sudo[28253]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:10 minidsp-shd volumio[28094]: info: Loading plugin "ms_surface_dial"... Feb 24 23:20:11 minidsp-shd volumio[28094]: Forking 3 albumart workers Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin ms_surface_dial Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Plugin example_plugin is not enabled Feb 24 23:20:11 minidsp-shd volumio[28094]: info: Loading plugin "hi_res_audio"... Feb 24 23:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2360. Feb 24 23:20:11 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:12 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:12 minidsp-shd go-librespot[28286]: Librespot-go daemon starting... Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=info msg="generated new device id: 5a18dfd181e0e8ede6ccd0b1522e94a4d86258f1" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:12 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:12+01:00" level=debug msg="zeroconf server listening on port 41219" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="obtained new client token: AAA3iXuIhUcZCUfg5Uwr3Yvi4M1Dn+MAko5QqSgcv3TTzbeCBOp5azXNbkOz9kjmHegiZmliY/IIfwWZx1VTcSC5FillddGnq1cBsxBuQwcQBDTfiUQYxHTs7pYHlVI4ynVwPvio8N1Z8MT9mxJGtrdgwLGI9cwbbDVisl8XVvhiFUvnO/7Qv7RYILRBQB24+fL40dSV/aAAPHvSwE2ta/iYV9z9591FXvaxWfTPk9F8coecLpxgqUbOdmY=" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:13 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=debug msg="completed challenge" Feb 24 23:20:13 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:13 minidsp-shd go-librespot[28286]: time="2025-02-24T23:20:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:13 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:14 minidsp-shd volumio[28094]: Starting albumart workers Feb 24 23:20:14 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin hi_res_audio Feb 24 23:20:14 minidsp-shd volumio[28094]: info: Loading plugin "inputs"... Feb 24 23:20:16 minidsp-shd volumio[28094]: info: Loading plugin "qobuz"... Feb 24 23:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:16 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2361. Feb 24 23:20:16 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:16 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:17 minidsp-shd go-librespot[28319]: Librespot-go daemon starting... Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=info msg="generated new device id: 87aaee5f3ffa9c2283d7722b7a1f22f7096b6dfb" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="zeroconf server listening on port 46767" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="obtained new client token: AAAFDt22FQcRP24ioT2Yyaxj8UsA/8noyHPv/zgh/6gfDBjoilx6czddoZlQBr7atNi4dlHhjGTpj0XFSWIB6YFlB9EtiHW61PoYguLjdJ4gGKiXl9G2UzUpYG3wNzks9577LaN4DSiEFj+ik5FGDejxz4RVtdQcUmxAK0e6miFNJ3mL6s6uPruvkZMrFSc5RxYitsZVmADlJe9zjaiVbWR2CcFcktvltX9FdX2B7doo1V/GkZbhVVfgytV9sw==" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:17 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:17+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:18 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:18+01:00" level=debug msg="completed challenge" Feb 24 23:20:18 minidsp-shd go-librespot[28319]: time="2025-02-24T23:20:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:18 minidsp-shd volumio[28094]: info: Loading plugin "tidal"... Feb 24 23:20:19 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:19] [connect] Successful connection Feb 24 23:20:20 minidsp-shd volumio[28094]: info: Loading plugin "oem_helper"... Feb 24 23:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:21 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2362. Feb 24 23:20:21 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:21 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:21 minidsp-shd go-librespot[28329]: Librespot-go daemon starting... Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=info msg="generated new device id: 872c13b9bbb40c27545ffd958a123a254377dca2" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:21 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:21+01:00" level=debug msg="zeroconf server listening on port 37605" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin oem_helper Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "updater_comm"... Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="obtained new client token: AAC/DEVyzDwNn6ODb2VR1W8DbcJPFrhw1s5ZubO3shYf7Z+2rQQQ6OCKBwPLQLAUeDedecIZrzNjwjST7IBGiSh1wNZyUaDHE/j9rLaqAutzp5g2cC4rduCtsNjO3fWqMjdHIMAF7WSjVTd7ePc8RDWLI0XO5zJH2oHcYHnSqk5L4D4Ps7ZNdzRi6pjIV5heTK+OhqdvaNDZSl4YLHmWVUAtgg8LaFTsZYgGObVddUm/i4h+LCD5oO2tejI=" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Plugin mpdemulation is not enabled Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "rest_api"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "websocket"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading plugin "80s80s"... Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Applying required configuration parameters for plugin 80s80s Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=debug msg="completed challenge" Feb 24 23:20:22 minidsp-shd volumio[28094]: info: [1740435622752] [80s80s] API delay: 15 Feb 24 23:20:22 minidsp-shd go-librespot[28329]: time="2025-02-24T23:20:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:22 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:22 minidsp-shd volumio[28094]: info: Loading i18n strings for locale it Feb 24 23:20:22 minidsp-shd volumio[28094]: Updating browse sources language Feb 24 23:20:22 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::initPlayerControls Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:23 minidsp-shd volumio[28094]: Express server listening on port 3000 Feb 24 23:20:23 minidsp-shd volumio[28094]: [Metrics] WebUI: 33s 912.48ms Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::resetVolumioState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::getcurrentVolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioRetrievevolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:23 minidsp-shd sudo[28347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:20:23 minidsp-shd sudo[28347]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd sudo[28347]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Feb 24 23:20:23 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Feb 24 23:20:23 minidsp-shd sudo[28350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:20:23 minidsp-shd sudo[28350]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd volumio[28094]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Completed loading Core Plugins Feb 24 23:20:23 minidsp-shd sudo[28350]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Preparing to generate the ALSA configuration file Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: Removed streaming files Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: volumioStreaming STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: SNAPSERVER STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: info: MRS: SNAPCLIENT STOPPED Feb 24 23:20:23 minidsp-shd volumio[28094]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Feb 24 23:20:23 minidsp-shd volumio[28094]: wlan0 Interface doesn't support scanning. Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Cannot use regular scanning, forcing with ap-force Feb 24 23:20:23 minidsp-shd sudo[28355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Feb 24 23:20:23 minidsp-shd sudo[28355]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:23 minidsp-shd sudo[28355]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:23 minidsp-shd volumio[28094]: command failed: No such device (-19) Feb 24 23:20:23 minidsp-shd volumio[28094]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Feb 24 23:20:23 minidsp-shd volumio[28094]: command failed: No such device (-19) Feb 24 23:20:23 minidsp-shd volumio[28094]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Feb 24 23:20:24 minidsp-shd volumio[28094]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Reading ALSA contributions from plugins. Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 1 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 2 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 3 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 4 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 5 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 6 Feb 24 23:20:24 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 7 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Reloading queue from file Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::setRepeat false single undefined Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::setRandom null Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Setting Device type: NanoPi NEO 3 Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Asound.conf file unchanged, so no further update is needed Feb 24 23:20:24 minidsp-shd volumio[28094]: info: Output device has changed, restarting MPD Feb 24 23:20:24 minidsp-shd sudo[28365]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 24 23:20:24 minidsp-shd sudo[28365]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:24 minidsp-shd sudo[28365]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd sudo[28368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:20:25 minidsp-shd sudo[28368]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28368]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Output device has changed, restarting Shairport Sync Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd sudo[28371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:20:25 minidsp-shd sudo[28371]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd systemd[1]: Stopping Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:20:25 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: ___________ START PLUGINS ___________ Feb 24 23:20:25 minidsp-shd volumio[28094]: info: ControllerMpd::onStart: Initializing MPD Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Creating MPD Configuration file Feb 24 23:20:25 minidsp-shd sudo[28380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:20:25 minidsp-shd sudo[28380]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28380]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:25 minidsp-shd volumio[28094]: info: [1740435625373] CoreMusicLibrary::Adding element Server multimediali Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:25 minidsp-shd sudo[28383]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:20:25 minidsp-shd sudo[28383]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:25 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:20:25 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding Manifest REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding METAVOLUMIO REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd sudo[28387]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD Feb 24 23:20:25 minidsp-shd sudo[28387]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd sudo[28387]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Preparing CD Folders Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding CD REST API Endpoints Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting UDEV Watcher for CD Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Detecting CD presence with UDEV Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:25 minidsp-shd volumio[28094]: info: [1740435625822] CoreMusicLibrary::Adding element Last_100 Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting RAAT Plugin Feb 24 23:20:25 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Additional UI Settings Added for plugin music_service/raat Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Streaming services startup Feb 24 23:20:25 minidsp-shd volumio[28094]: info: Starting Streaming Daemon Feb 24 23:20:25 minidsp-shd sudo[28396]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 24 23:20:25 minidsp-shd sudo[28396]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:25 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2363. Feb 24 23:20:25 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:26 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:26 minidsp-shd go-librespot[28401]: Librespot-go daemon starting... Feb 24 23:20:26 minidsp-shd sudo[28396]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=info msg="generated new device id: a029fba054e96e3947e663992333a7a007db5a30" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626117] CoreMusicLibrary::Adding element Webradio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding Calm Radio to Browse Sources Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626158] CoreMusicLibrary::Adding element Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd sudo[28410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Feb 24 23:20:26 minidsp-shd sudo[28410]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Creating Spotify config file Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:26 minidsp-shd systemd[1]: Stopping Volumio Tidal Connect Service... Feb 24 23:20:26 minidsp-shd systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:26 minidsp-shd systemd[1]: vtcs.service: Succeeded. Feb 24 23:20:26 minidsp-shd systemd[1]: Stopped Volumio Tidal Connect Service. Feb 24 23:20:26 minidsp-shd sudo[28410]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626454] CoreMusicLibrary::Adding element YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Feb 24 23:20:26 minidsp-shd volumio[28094]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="zeroconf server listening on port 46833" Feb 24 23:20:26 minidsp-shd volumio[28094]: error: Hi Res Audio Failed Login: Missing Login Data Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding HIGHRESAUDIO REST API Endpoints Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Refreshing QOBUZ token Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="obtained new client token: AAAv2XSl3LU0+ZxEoFPWRPPvOgTVU3WlBcpBK+kCjaQtE5629gAj9z8ZHQ2BZOKUClM6rFTTPNNVVSBpEIokte5SBmEZ7eAfc1a7hKgHo83hSbbgjb9TOqpQ/gbZJHQstZmROTcbslJbPfGWluHsC0TNnubAtdl6tmIwBSk245DveBNUZyu3e5Xf8NJWoo9mTyAy3596GdXhSKk+B61yPYtRu3H3Q2h5bf1CwPtxZ5SuEwBpitus9tX+aWfu1Q==" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:26 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:26+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:26 minidsp-shd volumio[28094]: info: [1740435626928] CoreMusicLibrary::Adding element 80s80s Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:26 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:26 minidsp-shd volumio[28094]: info: Volumio Calling Home Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Stopping AccessToken refresher cron Feb 24 23:20:27 minidsp-shd volumio[28094]: info: AccessToken refresher cron started Feb 24 23:20:27 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:27+01:00" level=debug msg="completed challenge" Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Adding TIDAL REST API Endpoints Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Feb 24 23:20:27 minidsp-shd go-librespot[28401]: time="2025-02-24T23:20:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Serial port opened successfully Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot start Volumio Streaming Daemon Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 24 23:20:27 minidsp-shd volumio[28094]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' Feb 24 23:20:27 minidsp-shd volumio[28094]: Can't get device info: No such device Feb 24 23:20:27 minidsp-shd volumio[28094]: info: MPD Permissions set Feb 24 23:20:27 minidsp-shd volumio[28094]: info: MPD Permissions set Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Upmpdcli Daemon Started Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial volumioupdatevolume callback: {"vol":100,"dbVolume":0,"disableVolumeControl":false} Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreStateMachine::pushState Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CorePlayQueue::getTrack 0 Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioPushState Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Ignoring ROON Volume update because of undefined data Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} Feb 24 23:20:27 minidsp-shd volumio[28094]: info: [msSurfaceDial init()] check /org/bluez Feb 24 23:20:27 minidsp-shd volumio[28094]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null Feb 24 23:20:27 minidsp-shd volumio[28094]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::Reload Ui Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Volumio called home Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Spotify config file written Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Feb 24 23:20:27 minidsp-shd volumio[28094]: info: updateDSP function in raat called! Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Updating RAAT Signal Path Feb 24 23:20:27 minidsp-shd volumio[28094]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Feb 24 23:20:27 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat Feb 24 23:20:27 minidsp-shd volumio[28094]: info: Reconfiguring and Restarting RAAT Plugin Feb 24 23:20:27 minidsp-shd sudo[28431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 24 23:20:27 minidsp-shd sudo[28431]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:27 minidsp-shd go-librespot[28434]: Librespot-go daemon starting... Feb 24 23:20:28 minidsp-shd sudo[28431]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: Not Reporting Auto name since its the default one Feb 24 23:20:28 minidsp-shd volumio[28094]: info: RAAT Overriding default device vendor model Feb 24 23:20:28 minidsp-shd volumio[28094]: info: Adding MINIDSP Inputs Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=info msg="generated new device id: c4a446d28184256cc19dda443f0f046648db055a" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:28 minidsp-shd volumio[28094]: info: [1740435628057] CoreMusicLibrary::Adding element Inputs Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:28 minidsp-shd volumio[28094]: info: [1740435628072] CoreMusicLibrary::Adding element Presets Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:28 minidsp-shd volumio[28094]: (node:28094) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Feb 24 23:20:28 minidsp-shd volumio[28094]: (Use `node --trace-deprecation ...` to show where the warning was created) Feb 24 23:20:28 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="zeroconf server listening on port 44261" Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:28 minidsp-shd volumio[28094]: info: No need to fix Spotify hosts Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="obtained new client token: AABdQyY5ZTW40BtHKkMy3VIHq3oNVTmzmBPcgnBWUjaOP97cjDHpxUuE5cddvfiFVJMoE9RoWrIUaNB/PenfKw+bvYTcU/Sd62Al/8fr+BMu+YiE+fN2gJw0qOZvFK6sC5XlNz3aChWhLZNAMeUaU0aqN3s0rvOZlyZmHTdMAPP+E0meCNmFyRPQR2+kBJaC1leZ7HLARncVEqLkev88K2mxwEQ7zug+OJWmgbFLK4rJAgXmxMgiUJCis9I8cA==" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:28 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:28+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:28 minidsp-shd sudo[28458]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Feb 24 23:20:28 minidsp-shd sudo[28458]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:28 minidsp-shd sudo[28458]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:28 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 9 Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumiosetSourceActiveno-source Feb 24 23:20:28 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:28 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Volumio BT Module successfully started Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd sudo[28461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28461]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Starting Shairport Sync Feb 24 23:20:29 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:29+01:00" level=debug msg="completed challenge" Feb 24 23:20:29 minidsp-shd sudo[28464]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28464]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:20:29 minidsp-shd go-librespot[28434]: time="2025-02-24T23:20:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:29 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Feb 24 23:20:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd sudo[28467]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:20:29 minidsp-shd sudo[28467]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd sudo[28464]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd sudo[28461]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd volumio[28094]: xcb_connection_has_error() returned true Feb 24 23:20:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:20:29 minidsp-shd sudo[28467]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: BQBhxErrnhkLo5hMGwQlaph0ue3bg87dLhDRB89Bl9RqH6YU9s7xpCOuHI9c4DnmF5E0FX6qWooGYBBvlriEF6RxjzbXnmsoNOOF9PFRdDR9jbBfMAkMZEaobSh-Ca8ZVGNHbGDB39Ga8_NmLgBmWJL910hCLGKT_NvmbMqMyzn5Iq7N4gU1Qs1GGZzFRmMbAprbCknYTyQ3wzsKFnfVnBESXB5v1TS1NDGiSwLjE0bkejXwpn7EHyYxuDG6uP5pGUXplFs-3jCsmAbX7XMvGxKuvw0404-M Feb 24 23:20:29 minidsp-shd volumio[28094]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: New Spotify access token = BQBhxErrnhkLo5hMGwQlaph0ue3bg87dLhDRB89Bl9RqH6YU9s7xpCOuHI9c4DnmF5E0FX6qWooGYBBvlriEF6RxjzbXnmsoNOOF9PFRdDR9jbBfMAkMZEaobSh-Ca8ZVGNHbGDB39Ga8_NmLgBmWJL910hCLGKT_NvmbMqMyzn5Iq7N4gU1Qs1GGZzFRmMbAprbCknYTyQ3wzsKFnfVnBESXB5v1TS1NDGiSwLjE0bkejXwpn7EHyYxuDG6uP5pGUXplFs-3jCsmAbX7XMvGxKuvw0404-M Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 24 23:20:29 minidsp-shd sudo[28475]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Feb 24 23:20:29 minidsp-shd sudo[28475]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:29 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Feb 24 23:20:29 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Feb 24 23:20:29 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Feb 24 23:20:29 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd systemd[1]: Started RAAT DAEMON. Feb 24 23:20:29 minidsp-shd sudo[28475]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:29 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Access Token successfully retrieved Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:20:29 minidsp-shd volumio[28094]: info: [1740435629881] CoreMusicLibrary::Adding element QOBUZ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source Calm Radio Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source YouTube Music Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source 80s80s Radio Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source Presets Feb 24 23:20:29 minidsp-shd volumio[28094]: Cannot find translation for source QOBUZ Feb 24 23:20:29 minidsp-shd volumio[28094]: info: Stopping AccessToken refresher cron for QOBUZ Feb 24 23:20:30 minidsp-shd volumio[28094]: info: AccessToken refresher cron started for QOBUZ Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Adding QOBUZ REST API Endpoints Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Enabling external Volume Control Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:20:30 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:20:30 minidsp-shd volumio[28094]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Raat Daemon started successfully Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: Error adding Membership: Error: addMembership EINVAL Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Shairport-Sync Started Feb 24 23:20:30 minidsp-shd volumio[28094]: info: TidalConnect service stoped! Feb 24 23:20:30 minidsp-shd volumio[28094]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Feb 24 23:20:30 minidsp-shd volumio[28094]: info: Executing endpoint restartRAATSocket Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Feb 24 23:20:30 minidsp-shd volumio[28094]: Searching all installed plugins Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: , search Feb 24 23:20:30 minidsp-shd volumio[28094]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 24 23:20:30 minidsp-shd volumio[28094]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:20:30 minidsp-shd volumio[28094]: TypeError: Cannot read property 'then' of undefined Feb 24 23:20:30 minidsp-shd volumio[28094]: at ControllerMpd.search (/volumio/app/plugins/music_service/mpd/index.js:1582:17) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Feb 24 23:20:30 minidsp-shd volumio[28094]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Feb 24 23:20:30 minidsp-shd volumio[28094]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Feb 24 23:20:30 minidsp-shd volumio[28094]: at Socket.emit (events.js:400:28) Feb 24 23:20:30 minidsp-shd volumio[28094]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 24 23:20:30 minidsp-shd volumio[28094]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Feb 24 23:20:30 minidsp-shd volumio[28094]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:20:31 minidsp-shd mpd[28386]: Feb 24 23:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 24 23:20:31 minidsp-shd systemd[1]: Started Music Player Daemon. Feb 24 23:20:31 minidsp-shd sudo[28371]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:31 minidsp-shd sudo[28383]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:31 minidsp-shd sudo[28505]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 23:19 Feb 24 23:20:31 minidsp-shd sudo[28505]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:31 minidsp-shd sudo[28505]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:32 minidsp-shd systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:32 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Feb 24 23:20:32 minidsp-shd systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 24 23:20:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:32 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2364. Feb 24 23:20:32 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:32 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:32 minidsp-shd systemd[1]: Started dynamicswap service. Feb 24 23:20:32 minidsp-shd go-librespot[28512]: Librespot-go daemon starting... Feb 24 23:20:32 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:32+01:00" level=info msg="generated new device id: 791ec28a73f2ccac430c67ac6089166b094308f5" Feb 24 23:20:32 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:32+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:32 minidsp-shd systemd[1]: dynamicswap.service: Succeeded. Feb 24 23:20:32 minidsp-shd systemd[1]: raat-daemon.service: Service RestartSec=100ms expired, scheduling restart. Feb 24 23:20:32 minidsp-shd systemd[1]: raat-daemon.service: Scheduled restart job, restart counter is at 1. Feb 24 23:20:32 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Feb 24 23:20:32 minidsp-shd systemd[1]: Started RAAT DAEMON. Feb 24 23:20:32 minidsp-shd systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Feb 24 23:20:32 minidsp-shd systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4. Feb 24 23:20:32 minidsp-shd systemd[1]: Stopped Volumio Backend Module. Feb 24 23:20:32 minidsp-shd systemd[1]: Started Volumio Backend Module. Feb 24 23:20:32 minidsp-shd systemd[1]: Started dynamicswap service. Feb 24 23:20:32 minidsp-shd systemd[1]: dynamicswap.service: Succeeded. Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="zeroconf server listening on port 43603" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="obtained new client token: AABQVU1/NMY6W9tW7ulRVIVeGhp6s9CAjSWMHFNaB0XcdZdN/jFjrhh9CaqBvKUfkM6SEW949LT/9u6SRk16v7Axm6V6uSJ9sC+l5JmJzsTZd74pfImAI+gaGtsbIwMjtc83awU/eekIx9jD/8QiWCHG/n6vVA7evwZOnPf49L0i0+A+q59tc2eKCNwnIWCH/sj91WpP0ifeSR6dRLjXs0lidwhNX2yrXqgSheR/cYvG56h9H4iXeHdhj10=" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=debug msg="completed challenge" Feb 24 23:20:33 minidsp-shd go-librespot[28512]: time="2025-02-24T23:20:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:34 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:34] [info] asio async_connect error: system:111 (Connection refused) Feb 24 23:20:34 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:34] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 24 23:20:34 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:34] [error] handle_connect error: Underlying Transport Error Feb 24 23:20:35 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:20:35 minidsp-shd volumio[28526]: info: ----- Volumio3 ---- Feb 24 23:20:35 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:20:35 minidsp-shd volumio[28526]: info: ----- System startup ---- Feb 24 23:20:35 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:20:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2365. Feb 24 23:20:36 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:37 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:37 minidsp-shd go-librespot[28560]: Librespot-go daemon starting... Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=info msg="generated new device id: b7caad0e5e00de56db5786d2f5d1a8382d8b4801" Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:37 minidsp-shd volumio[28526]: info: MYVOLUMIO Environment detected Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Plugin folders cleanup Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning into folder /volumio/app/plugins/ Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category audio_interface Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category miscellanea Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category music_service Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category plugins.json Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category system_controller Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category user_interface Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning into folder /data/plugins/ Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Scanning category music_service Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Plugin folders cleanup completed Feb 24 23:20:37 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:20:37 minidsp-shd volumio[28526]: info: ----- Core plugins startup ---- Feb 24 23:20:37 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Loading plugins from folder /volumio/app/plugins/ Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin bluetooth to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin multiroom to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin upnp to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin metavolumio to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin ms_surface_dial to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin cd_controller to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin raat to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="zeroconf server listening on port 37013" Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Loading plugins from folder /data/plugins/ Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Loading plugin "system"... Feb 24 23:20:37 minidsp-shd volumio[28526]: info: Loading plugin "appearance"... Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="obtained new client token: AAD1lNEQi80npNGbjMAwhCHXdkNfkcb7Ik2LTfs97wDh/ed7j4iDRw3q0JrkprMFtEdih/GMrN9Y8EcukrjwrKDKk7lnJTfC3BwqVLeQwKj4dIMI2xSIhgI7xcS4uSACUyOR8KJfoOZH1FgHVDrbhZ+45gRdk8oS1WDm26OYnEbpqz34kKyonej1QqMwQgv3eILmvOrrxjHhvSo31sh6NdAOe5rqv8TqUM1iGqz3AWHc7BeTKbsVp8/49Ru7OA==" Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:37 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:37+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:38 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:38+01:00" level=debug msg="completed challenge" Feb 24 23:20:38 minidsp-shd go-librespot[28560]: time="2025-02-24T23:20:38+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:38 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:38 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "network"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Refreshing Cached IP Addresses Feb 24 23:20:39 minidsp-shd sudo[28574]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:20:39 minidsp-shd sudo[28574]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:39 minidsp-shd sudo[28574]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "services"... Feb 24 23:20:39 minidsp-shd sudo[28576]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:20:39 minidsp-shd sudo[28576]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "alsa_controller"... Feb 24 23:20:39 minidsp-shd sudo[28579]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 24 23:20:39 minidsp-shd sudo[28579]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:39 minidsp-shd sudo[28576]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:39 minidsp-shd sudo[28579]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "wizard"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "networkfs"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Starting Udev Watcher for removable devices Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Ignoring mount for partition: BOOT Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Ignoring mount for partition: volumio Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Ignoring mount for partition: volumio_data Feb 24 23:20:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "volumio_command_line_client"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "upnp"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: [1740435639685] Starting Upmpd Daemon Feb 24 23:20:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "my_music"... Feb 24 23:20:39 minidsp-shd volumio[28526]: info: Loading plugin "mpd"... Feb 24 23:20:40 minidsp-shd volumio[28526]: info: Loading plugin "upnp_browser"... Feb 24 23:20:40 minidsp-shd volumio[28526]: info: Loading plugin "bluetooth"... Feb 24 23:20:41 minidsp-shd volumio[28526]: info: [1740435641203] Starting BluetoothController Feb 24 23:20:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2366. Feb 24 23:20:41 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:41 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:41 minidsp-shd go-librespot[28591]: Librespot-go daemon starting... Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=info msg="generated new device id: 279e94d6e77c859ef792cb7a49f34cd2bcb764bc" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:41 minidsp-shd volumio[28526]: info: Loading plugin "alarm-clock"... Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="zeroconf server listening on port 33303" Feb 24 23:20:41 minidsp-shd volumio[28526]: info: Loading plugin "manifestui"... Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="obtained new client token: AACCd2kVnwnnGqxgVIiEvAPK/b6aASWASIgB4xSJ0JDNa/JrtN3H7vtbCv2BrW5RvtvFIDDh9CK42fafaGzgZjhJdNz/nAO6l+z4SEhONPkUfQRtY/ZVz480jwOX/d/GtRpbeJmVzg4BBaGEqE+IuOX+6qF0Y+9/4VwV4YTKkQqF421AqqDJbb6vhHILc/n699mb7JLygXoCViDL4VnLb4UNYlH+wTMmy11WCUO3F9YrkzyXZqn89arkn6c40g==" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:41 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:41+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:42 minidsp-shd volumio[28526]: info: Loading plugin "metavolumio"... Feb 24 23:20:42 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:42+01:00" level=debug msg="completed challenge" Feb 24 23:20:42 minidsp-shd go-librespot[28591]: time="2025-02-24T23:20:42+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:42 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:43 minidsp-shd volumio[28526]: info: Loading plugin "airplay_emulation"... Feb 24 23:20:43 minidsp-shd volumio[28526]: info: Starting Shairport Sync Feb 24 23:20:43 minidsp-shd volumio[28526]: info: Loading plugin "cd_controller"... Feb 24 23:20:44 minidsp-shd volumio[28526]: info: Loading plugin "last_100"... Feb 24 23:20:44 minidsp-shd volumio[28526]: info: Loading plugin "raat"... Feb 24 23:20:44 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:44] [connect] Successful connection Feb 24 23:20:44 minidsp-shd volumio[28526]: info: RAAT Plugin loaded Feb 24 23:20:44 minidsp-shd volumio[28526]: info: Adding restartRAATSocket REST API Endpoint Feb 24 23:20:44 minidsp-shd volumio[28526]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat Feb 24 23:20:44 minidsp-shd volumio[28526]: info: Loading plugin "streaming_services"... Feb 24 23:20:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:45 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2367. Feb 24 23:20:45 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:45 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:45 minidsp-shd go-librespot[28599]: Librespot-go daemon starting... Feb 24 23:20:45 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:45+01:00" level=info msg="generated new device id: e139be9bbd62b50a1ce3b970483a4a800a8c4033" Feb 24 23:20:45 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:45+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Starting Streaming Service Transparent Proxy Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="zeroconf server listening on port 34469" Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Loading plugin "tidalconnect"... Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="obtained new client token: AABel1/wpLXpjFjoffprcWZY1kBTwhTCmolAtq8XaSTPJwNEjvO8UBArQXNtdu4p0BeAUNTbuSMvMRccUeTk7J7RrP29NjyQrTg1ljSAE5gjEP5RpSbsoXXqj+RRWKnvI9ij/qsM3U2m+QxVxyQt5oiEiu66JxKJzqu1aSDyvBE/gi7+jwtxnSfsAtvsokplgAdrQPBpDCegMKBZe18w6WxSzoPQcUzrQrCQm1GfFUiMj44ahCQGf2rLA6lULQ==" Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Loading plugin "webradio"... Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Loading plugin "i2s_dacs"... Feb 24 23:20:46 minidsp-shd volumio[28526]: info: I2S DAC not set, start Auto-detection Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Loading plugin "volumiodiscovery"... Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** For more information see Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:46 minidsp-shd volumio[28526]: *** WARNING *** For more information see Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** For more information see Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 24 23:20:46 minidsp-shd node[28526]: *** WARNING *** For more information see Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Discovery: Started advertising with name: miniDSP SHD Feb 24 23:20:46 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:20:46 minidsp-shd volumio[28526]: info: Loading plugin "calmradio"... Feb 24 23:20:46 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:46+01:00" level=debug msg="completed challenge" Feb 24 23:20:47 minidsp-shd go-librespot[28599]: time="2025-02-24T23:20:47+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:47 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:47 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:48 minidsp-shd volumio[28526]: STREAMING PROXY: Starting server on port 3245 Feb 24 23:20:48 minidsp-shd volumio[28526]: Node JS runtime: 14 Feb 24 23:20:48 minidsp-shd volumio[28526]: info: Loading plugin "spop"... Feb 24 23:20:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:50 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2368. Feb 24 23:20:50 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:50 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:50 minidsp-shd go-librespot[28617]: Librespot-go daemon starting... Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=info msg="generated new device id: dd0f3b06e76939bcc710537354c1907c43a0759c" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:50 minidsp-shd volumio[28526]: info: Loading plugin "ytmusic"... Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="zeroconf server listening on port 38217" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="obtained new client token: AADIahpzW02IHdtkk9uvo9d+uvMs7GIw5eey2FJx0WZbnd3EG4QhcI52MibVyYuvFbHYoLbS2kxHSFlALLM+PC+b00Z/Gw1wUeg0NvXXsng03LmCCTbMUMGucfHKldF9OFQm46dBMRXscCQYssnm+cRxamoDb4xRsc1LT1f++QdVBXcav0c87c4s3sMuYctwI9CgWNiNuzChDhVI3K2uyTU5S/ejjW3RCvIEaQZoSAeaVNZ9uIAe+DaRh+HhPA==" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:50 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:50+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:51 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:51+01:00" level=debug msg="completed challenge" Feb 24 23:20:51 minidsp-shd go-librespot[28617]: time="2025-02-24T23:20:51+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:51 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:51 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:52 minidsp-shd volumio[28526]: info: Loading plugin "multiroom"... Feb 24 23:20:54 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin multiroom Feb 24 23:20:54 minidsp-shd sudo[28665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Feb 24 23:20:54 minidsp-shd sudo[28665]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:54 minidsp-shd sudo[28665]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:54 minidsp-shd volumio[28526]: /bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Feb 24 23:20:54 minidsp-shd volumio[28526]: info: MRS: MultiRoom plugin initialized Feb 24 23:20:54 minidsp-shd volumio[28526]: info: MRS: STOPPING SNAPCLIENT Feb 24 23:20:54 minidsp-shd volumio[28526]: info: MRS: Snap server stop Feb 24 23:20:54 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:54 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2369. Feb 24 23:20:54 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:54 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:54 minidsp-shd sudo[28681]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Feb 24 23:20:54 minidsp-shd sudo[28681]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:54 minidsp-shd volumio[28526]: info: MRS: STOPPING volumioStreaming Feb 24 23:20:54 minidsp-shd go-librespot[28683]: Librespot-go daemon starting... Feb 24 23:20:54 minidsp-shd sudo[28686]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Feb 24 23:20:54 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:54+01:00" level=info msg="generated new device id: 7bf43ccf90384170df7dee913ef4ac54d4b1cfc7" Feb 24 23:20:54 minidsp-shd sudo[28686]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:54 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:54+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:54 minidsp-shd sudo[28681]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:54 minidsp-shd volumio[28526]: info: Loading plugin "outputs"... Feb 24 23:20:54 minidsp-shd sudo[28694]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Feb 24 23:20:54 minidsp-shd sudo[28694]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:54 minidsp-shd volumio[28526]: info: Loading plugin "albumart"... Feb 24 23:20:54 minidsp-shd sudo[28697]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Feb 24 23:20:54 minidsp-shd sudo[28697]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:20:54 minidsp-shd sudo[28697]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:54 minidsp-shd sudo[28686]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:54 minidsp-shd volumio[28526]: info: Loading plugin "ms_surface_dial"... Feb 24 23:20:54 minidsp-shd sudo[28694]: pam_unix(sudo:session): session closed for user root Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="zeroconf server listening on port 36247" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="obtained new client token: AAB1CeuU9eX6zzWzJGHRwM7hGzJ+BD76SK1m7kxLqdnQ18GdqfD7oD+v4II3eipEEosr24ejFJU9ZRVeJQTLvkkiGtrPqAZaJnEcCh0kdF5VpEuq/C94tb2Voi+fWFcPkiZygzbCxeIl+QG4lCeXruyx7Lyl5y5/jPjpirfCFF1w4voQZ1FcdbVHVzcRCuR0KyZ2Slyr+mSbleMCS7UXr0tcE7Im5A8gPG89JmgaLBNEd7VRWxa3R0W0+S3MPQ==" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:20:55 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:55+01:00" level=debug msg="completed keyexchange" Feb 24 23:20:55 minidsp-shd volumio[28526]: Forking 3 albumart workers Feb 24 23:20:56 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin ms_surface_dial Feb 24 23:20:56 minidsp-shd volumio[28526]: info: Plugin example_plugin is not enabled Feb 24 23:20:56 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:56+01:00" level=debug msg="completed challenge" Feb 24 23:20:56 minidsp-shd volumio[28526]: info: Loading plugin "hi_res_audio"... Feb 24 23:20:56 minidsp-shd go-librespot[28683]: time="2025-02-24T23:20:56+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:20:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:20:56 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:20:57 minidsp-shd volumio[28526]: Starting albumart workers Feb 24 23:20:57 minidsp-shd volumio[28526]: Starting albumart workers Feb 24 23:20:57 minidsp-shd volumio[28526]: Starting albumart workers Feb 24 23:20:58 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin hi_res_audio Feb 24 23:20:58 minidsp-shd volumio[28526]: info: Loading plugin "inputs"... Feb 24 23:20:59 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:20:59] [connect] Successful connection Feb 24 23:20:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:20:59 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2370. Feb 24 23:20:59 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:20:59 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:20:59 minidsp-shd go-librespot[28748]: Librespot-go daemon starting... Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=info msg="generated new device id: 9c08274d92fa74d597d11cd3b91220b652f905af" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="zeroconf server listening on port 43695" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=debug msg="obtained new client token: AABj/q6ZlXHiHwB154SR9c0g1PizlRm/GIMjXGMZTlE3Ww3btyswk+aDedHlD/ZwovQ7emeiv8a2Qyl33A+JZLOs46+rk68DYqpUQorFKsnOAby3PoKJNxgCSj+ZilyAclUW280qbFIPRf6yYZVioUOI+1UFSWbKIKDS4hYQlyfZtXM0Z3OpIWNAfQ7Sh8GgYCIBWS7N+ypfvtWTrZwXqXAPa5lVG6m71897WqmdofM9Xtc5EYKpBZDIY5P+DQ==" Feb 24 23:20:59 minidsp-shd go-librespot[28748]: time="2025-02-24T23:20:59+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:00 minidsp-shd go-librespot[28748]: time="2025-02-24T23:21:00+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:00 minidsp-shd volumio[28526]: info: Loading plugin "qobuz"... Feb 24 23:21:00 minidsp-shd go-librespot[28748]: time="2025-02-24T23:21:00+01:00" level=debug msg="completed challenge" Feb 24 23:21:00 minidsp-shd go-librespot[28748]: time="2025-02-24T23:21:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:00 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:00 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:01 minidsp-shd volumio[28526]: info: Loading plugin "tidal"... Feb 24 23:21:03 minidsp-shd volumio[28526]: info: Loading plugin "oem_helper"... Feb 24 23:21:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:03 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2371. Feb 24 23:21:03 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:03 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:03 minidsp-shd go-librespot[28761]: Librespot-go daemon starting... Feb 24 23:21:03 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:03+01:00" level=info msg="generated new device id: 7dfe1882bac6701dbf391876ea31ab5295f6c3dc" Feb 24 23:21:03 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:03+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="zeroconf server listening on port 35501" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="obtained new client token: AAAMibtIiKkunI3GWVDc59+ffUx1dodiBJ9qQbPcM098jWcLC0/qxznXRgvIyg1xd/HPIbiFolLHIPqSpHiZta0RRyq3oFvVpcO+6FJvF1maVODGHqQe7JitdzNSJwukIv2bwrdKDXxLbAcqzoQbrJJxPetJBNkQIoaJCLpkTHKMo12RaYuHUIRp9o95ubCy9w53AXmO/uwa8Pp6B5t89+pM7j9NuiFeeDBIpfV+tqviEYSldP+Gvk3QxJ5Vmg==" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:04 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:04+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:04 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin oem_helper Feb 24 23:21:04 minidsp-shd volumio[28526]: info: Loading plugin "updater_comm"... Feb 24 23:21:05 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:05+01:00" level=debug msg="completed challenge" Feb 24 23:21:05 minidsp-shd go-librespot[28761]: time="2025-02-24T23:21:05+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:05 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Plugin mpdemulation is not enabled Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Loading plugin "rest_api"... Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Loading plugin "websocket"... Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Loading plugin "80s80s"... Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Applying required configuration parameters for plugin 80s80s Feb 24 23:21:05 minidsp-shd volumio[28526]: info: [1740435665709] [80s80s] API delay: 15 Feb 24 23:21:05 minidsp-shd volumio[28526]: info: Loading i18n strings for locale it Feb 24 23:21:05 minidsp-shd volumio[28526]: Updating browse sources language Feb 24 23:21:05 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::initPlayerControls Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:21:06 minidsp-shd volumio[28526]: Express server listening on port 3000 Feb 24 23:21:06 minidsp-shd volumio[28526]: [Metrics] WebUI: 31s 243.42ms Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreStateMachine::resetVolumioState Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreStateMachine::getcurrentVolume Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioRetrievevolume Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:06 minidsp-shd sudo[28780]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:21:06 minidsp-shd sudo[28780]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:06 minidsp-shd sudo[28780]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Feb 24 23:21:06 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Feb 24 23:21:06 minidsp-shd sudo[28783]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:21:06 minidsp-shd sudo[28783]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:06 minidsp-shd volumio[28526]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Feb 24 23:21:06 minidsp-shd volumio[28526]: info: Completed loading Core Plugins Feb 24 23:21:06 minidsp-shd volumio[28526]: info: Preparing to generate the ALSA configuration file Feb 24 23:21:06 minidsp-shd sudo[28783]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:06 minidsp-shd volumio[28526]: info: MRS: Removed streaming files Feb 24 23:21:06 minidsp-shd volumio[28526]: info: MRS: volumioStreaming STOPPED Feb 24 23:21:06 minidsp-shd volumio[28526]: info: MRS: SNAPSERVER STOPPED Feb 24 23:21:06 minidsp-shd volumio[28526]: info: MRS: SNAPCLIENT STOPPED Feb 24 23:21:06 minidsp-shd volumio[28526]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Feb 24 23:21:06 minidsp-shd volumio[28526]: wlan0 Interface doesn't support scanning. Feb 24 23:21:06 minidsp-shd volumio[28526]: info: Cannot use regular scanning, forcing with ap-force Feb 24 23:21:06 minidsp-shd sudo[28788]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Feb 24 23:21:06 minidsp-shd sudo[28788]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:06 minidsp-shd sudo[28788]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:06 minidsp-shd volumio[28526]: command failed: No such device (-19) Feb 24 23:21:06 minidsp-shd volumio[28526]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Feb 24 23:21:06 minidsp-shd volumio[28526]: command failed: No such device (-19) Feb 24 23:21:06 minidsp-shd volumio[28526]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Feb 24 23:21:06 minidsp-shd volumio[28526]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Feb 24 23:21:06 minidsp-shd volumio[28526]: info: Reading ALSA contributions from plugins. Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Reloading queue from file Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreStateMachine::setRepeat false single undefined Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreStateMachine::setRandom null Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Setting Device type: NanoPi NEO 3 Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Asound.conf file unchanged, so no further update is needed Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Output device has changed, restarting MPD Feb 24 23:21:07 minidsp-shd sudo[28798]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 24 23:21:07 minidsp-shd sudo[28798]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:07 minidsp-shd sudo[28798]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:07 minidsp-shd sudo[28801]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:21:07 minidsp-shd sudo[28801]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:07 minidsp-shd sudo[28801]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Output device has changed, restarting Shairport Sync Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:07 minidsp-shd sudo[28804]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:21:07 minidsp-shd sudo[28804]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:07 minidsp-shd systemd[1]: Stopping Music Player Daemon... Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:21:07 minidsp-shd volumio[28526]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:07 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:21:07 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:21:07 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:21:07 minidsp-shd volumio[28526]: info: ___________ START PLUGINS ___________ Feb 24 23:21:07 minidsp-shd volumio[28526]: info: ControllerMpd::onStart: Initializing MPD Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Creating MPD Configuration file Feb 24 23:21:07 minidsp-shd sudo[28813]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 24 23:21:07 minidsp-shd sudo[28813]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:07 minidsp-shd sudo[28813]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:07 minidsp-shd volumio[28526]: info: [1740435667869] CoreMusicLibrary::Adding element Server multimediali Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:07 minidsp-shd sudo[28816]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 24 23:21:07 minidsp-shd sudo[28816]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:07 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 24 23:21:07 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 24 23:21:07 minidsp-shd systemd[1]: mpd.service: Succeeded. Feb 24 23:21:07 minidsp-shd systemd[1]: Stopped Music Player Daemon. Feb 24 23:21:07 minidsp-shd systemd[1]: Starting Music Player Daemon... Feb 24 23:21:07 minidsp-shd volumio[28526]: info: Adding Manifest REST API Endpoints Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding METAVOLUMIO REST API Endpoints Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:08 minidsp-shd sudo[28820]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD Feb 24 23:21:08 minidsp-shd sudo[28820]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:08 minidsp-shd sudo[28820]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 23:21:08 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2372. Feb 24 23:21:08 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Preparing CD Folders Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding CD REST API Endpoints Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Starting UDEV Watcher for CD Feb 24 23:21:08 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Detecting CD presence with UDEV Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Feb 24 23:21:08 minidsp-shd go-librespot[28828]: Librespot-go daemon starting... Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=info msg="generated new device id: 5c46670dc360852b041ccf4aa78568f6e0c286c2" Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:08 minidsp-shd volumio[28526]: info: [1740435668330] CoreMusicLibrary::Adding element Last_100 Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Starting RAAT Plugin Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Additional UI Settings Added for plugin music_service/raat Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Streaming services startup Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Starting Streaming Daemon Feb 24 23:21:08 minidsp-shd sudo[28836]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 24 23:21:08 minidsp-shd sudo[28836]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:08 minidsp-shd sudo[28836]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:08 minidsp-shd volumio[28526]: info: [1740435668629] CoreMusicLibrary::Adding element Webradio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:21:08 minidsp-shd sudo[28843]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Feb 24 23:21:08 minidsp-shd sudo[28843]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Adding Calm Radio to Browse Sources Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:08 minidsp-shd volumio[28526]: info: [1740435668683] CoreMusicLibrary::Adding element Calm Radio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:08 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:08 minidsp-shd volumio[28526]: info: Creating Spotify config file Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:08 minidsp-shd sudo[28843]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="zeroconf server listening on port 40695" Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=debug msg="obtained new client token: AADvoWo1CvEhdIQUCDVpUJWRSN3ogEHfK0SRqx2MpcBbUY/0oWHKLJsU4d0IvPmsd8Q0a09FMK+GHtzyEchvA7stW7v6LxaEeV6UMOtObdepQ5NgVOphsUvuo5ObxC38r4k83nB2Zy+jnNBblOcVJfBvPI2bmFPG1G/xbckkgLv9Se5T4FWb1apqjDv9T5RRofgunv42XlvOTdc/9yz3bRmoJ55E18Pe1WuhflGgAB8X+LAto7zBfanYeal3qA==" Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:08 minidsp-shd volumio[28526]: info: [1740435668961] CoreMusicLibrary::Adding element YouTube Music Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:08 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:08 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:08 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Feb 24 23:21:08 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:08+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:09 minidsp-shd volumio[28526]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 24 23:21:09 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:09 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:09+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:09 minidsp-shd volumio[28526]: error: Hi Res Audio Failed Login: Missing Login Data Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Adding HIGHRESAUDIO REST API Endpoints Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Refreshing QOBUZ token Feb 24 23:21:09 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:21:09 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:09 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:09 minidsp-shd volumio[28526]: info: [1740435669365] CoreMusicLibrary::Adding element 80s80s Radio Feb 24 23:21:09 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:09 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:09 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:09 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Volumio Calling Home Feb 24 23:21:09 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:09+01:00" level=debug msg="completed challenge" Feb 24 23:21:09 minidsp-shd go-librespot[28828]: time="2025-02-24T23:21:09+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:09 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Stopping AccessToken refresher cron Feb 24 23:21:09 minidsp-shd volumio[28526]: info: AccessToken refresher cron started Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Adding TIDAL REST API Endpoints Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Serial port opened successfully Feb 24 23:21:09 minidsp-shd volumio[28526]: error: Cannot start Volumio Streaming Daemon Feb 24 23:21:09 minidsp-shd volumio[28526]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 24 23:21:09 minidsp-shd volumio[28526]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 24 23:21:09 minidsp-shd volumio[28526]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' Feb 24 23:21:09 minidsp-shd volumio[28526]: Can't get device info: No such device Feb 24 23:21:09 minidsp-shd volumio[28526]: info: MPD Permissions set Feb 24 23:21:09 minidsp-shd volumio[28526]: info: MPD Permissions set Feb 24 23:21:09 minidsp-shd volumio[28526]: info: Upmpdcli Daemon Started Feb 24 23:21:10 minidsp-shd volumio[28526]: info: msSurfaceDial volumioupdatevolume callback: {"vol":100,"dbVolume":0,"disableVolumeControl":false} Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Ignoring ROON Volume update because of undefined data Feb 24 23:21:10 minidsp-shd volumio[28526]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} Feb 24 23:21:10 minidsp-shd volumio[28526]: info: [msSurfaceDial init()] check /org/bluez Feb 24 23:21:10 minidsp-shd volumio[28526]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null Feb 24 23:21:10 minidsp-shd volumio[28526]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::Reload Ui Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Volumio called home Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Spotify config file written Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Feb 24 23:21:10 minidsp-shd volumio[28526]: info: updateDSP function in raat called! Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Updating RAAT Signal Path Feb 24 23:21:10 minidsp-shd volumio[28526]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Reconfiguring and Restarting RAAT Plugin Feb 24 23:21:10 minidsp-shd sudo[28865]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 24 23:21:10 minidsp-shd sudo[28865]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:10 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:10 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:10 minidsp-shd go-librespot[28868]: Librespot-go daemon starting... Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd sudo[28865]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Not Reporting Auto name since its the default one Feb 24 23:21:10 minidsp-shd volumio[28526]: info: RAAT Overriding default device vendor model Feb 24 23:21:10 minidsp-shd volumio[28526]: info: Adding MINIDSP Inputs Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:10 minidsp-shd volumio[28526]: info: [1740435670330] CoreMusicLibrary::Adding element Inputs Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=info msg="generated new device id: e106d48ec8cbfb2ccf5769e02d0d68e767d9e218" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:10 minidsp-shd volumio[28526]: info: [1740435670343] CoreMusicLibrary::Adding element Presets Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:10 minidsp-shd volumio[28526]: Cannot find translation for source Presets Feb 24 23:21:10 minidsp-shd volumio[28526]: (node:28526) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Feb 24 23:21:10 minidsp-shd volumio[28526]: (Use `node --trace-deprecation ...` to show where the warning was created) Feb 24 23:21:10 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Feb 24 23:21:10 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:10 minidsp-shd volumio[28526]: info: No need to fix Spotify hosts Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="zeroconf server listening on port 38213" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=debug msg="obtained new client token: AACAjC/ZxMShkbjpwjkraKKu1DxeAxksOYmkdded76cBfCnjULGUF3AWxV65Zz00g5VNdI/dp4fI3XjB974d1ag31c/IQNwDTM8LFeZ657XUpuYNfuQihXwGfukjwgmnfyZuWbmz+btS9NH+YlxK5HbGN3c1FVZ7RVQuPndioqHL4yt29DMWuyRJ8SKZT09kmEoGH4AuNbVWgTrkqmBKF7167wskahFaRrrT1QQNaH/PHB6pAprdmoTq6t+flw==" Feb 24 23:21:10 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:10+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:11 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:11+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Access Token successfully retrieved Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:11 minidsp-shd volumio[28526]: info: [1740435671080] CoreMusicLibrary::Adding element QOBUZ Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source Presets Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source QOBUZ Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Stopping AccessToken refresher cron for QOBUZ Feb 24 23:21:11 minidsp-shd volumio[28526]: info: AccessToken refresher cron started for QOBUZ Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Adding QOBUZ REST API Endpoints Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Feb 24 23:21:11 minidsp-shd sudo[28892]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Feb 24 23:21:11 minidsp-shd sudo[28892]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:11 minidsp-shd sudo[28892]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Starting Shairport Sync Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Starting Shairport Sync Feb 24 23:21:11 minidsp-shd sudo[28895]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:21:11 minidsp-shd sudo[28895]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Starting Shairport Sync Feb 24 23:21:11 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:11+01:00" level=debug msg="completed challenge" Feb 24 23:21:11 minidsp-shd sudo[28898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:21:11 minidsp-shd sudo[28898]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:11 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:21:11 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:21:11 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Feb 24 23:21:11 minidsp-shd go-librespot[28868]: time="2025-02-24T23:21:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:11 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd sudo[28895]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:11 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:11 minidsp-shd sudo[28901]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 23:21:11 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:21:11 minidsp-shd sudo[28901]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:11 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 24 23:21:11 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:21:11 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd sudo[28898]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:11 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 24 23:21:11 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 24 23:21:11 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Feb 24 23:21:11 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 24 23:21:11 minidsp-shd sudo[28901]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:11 minidsp-shd volumio[28526]: xcb_connection_has_error() returned true Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumiosetSourceActiveno-source Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source Presets Feb 24 23:21:11 minidsp-shd volumio[28526]: Cannot find translation for source QOBUZ Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioStop Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreStateMachine::stop Feb 24 23:21:11 minidsp-shd volumio[28526]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:21:11 minidsp-shd volumio[28526]: info: Notifying Active Input {"trackType":"input","service":"inputs","title":"TOSLINK","disableUiControls":true,"albumart":"/albumart"} Feb 24 23:21:12 minidsp-shd sudo[28909]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:21:12 minidsp-shd sudo[28909]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:12 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Feb 24 23:21:12 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Feb 24 23:21:12 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Feb 24 23:21:12 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Feb 24 23:21:12 minidsp-shd systemd[1]: Started RAAT DAEMON. Feb 24 23:21:12 minidsp-shd sudo[28909]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Volumio BT Module successfully started Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Enabling external Volume Control Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:12 minidsp-shd volumio[28526]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:21:12 minidsp-shd volumio[28526]: SPOTIFY: BQCCnzCbqnnieJalqFtusW3ZeaB1i3hW26o4CZaKKWJe8dTkmo0MvIckKeJq8O1r2IBlUSspZZPTSW6Orq-CTL9KsnFZmAzmXxqJYp6q5NeYICYHwZvBzYKi2Q73Uws8sKo49xcdFqLaq-FNPf41giADK6tjRcJv1JlpN2YaP60j6sMO4fyGOOAXzj7inrEuQ9Rd7M81N2UrymRAHpCD4mw2FjmOP18qheoNtOpvDgV72PEuPsYZLmlc2b6zXMx-0UhC3kHVRWwKfI3aFkt257g8o2XOcCTG Feb 24 23:21:12 minidsp-shd volumio[28526]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Feb 24 23:21:12 minidsp-shd volumio[28526]: info: New Spotify access token = BQCCnzCbqnnieJalqFtusW3ZeaB1i3hW26o4CZaKKWJe8dTkmo0MvIckKeJq8O1r2IBlUSspZZPTSW6Orq-CTL9KsnFZmAzmXxqJYp6q5NeYICYHwZvBzYKi2Q73Uws8sKo49xcdFqLaq-FNPf41giADK6tjRcJv1JlpN2YaP60j6sMO4fyGOOAXzj7inrEuQ9Rd7M81N2UrymRAHpCD4mw2FjmOP18qheoNtOpvDgV72PEuPsYZLmlc2b6zXMx-0UhC3kHVRWwKfI3aFkt257g8o2XOcCTG Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Raat Daemon started successfully Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Shairport-Sync Started Feb 24 23:21:12 minidsp-shd volumio[28526]: Error adding Membership: Error: addMembership EINVAL Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Shairport-Sync Started Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Shairport-Sync Started Feb 24 23:21:12 minidsp-shd volumio[28526]: info: TidalConnect service stoped! Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::servicePushState Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:12 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Feb 24 23:21:12 minidsp-shd volumio[28526]: info: Executing endpoint restartRAATSocket Feb 24 23:21:12 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:13 minidsp-shd volumio[28526]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Feb 24 23:21:13 minidsp-shd volumio[28526]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Feb 24 23:21:13 minidsp-shd sudo[28933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Feb 24 23:21:13 minidsp-shd sudo[28933]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:13 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. Feb 24 23:21:13 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 Feb 24 23:21:13 minidsp-shd sudo[28933]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:13 minidsp-shd volumio[28526]: info: msSurfaceDial volumioupdatevolume callback: {"vol":100,"dbVolume":0,"mute":false,"disableVolumeControl":false} Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:13 minidsp-shd volumio[28526]: error: Help! Some callbacks for volumioPushState are crashing! Feb 24 23:21:13 minidsp-shd volumio[28526]: error: Cannot read property 'sendVolumeMute' of undefined Feb 24 23:21:13 minidsp-shd mpd[28819]: Feb 24 23:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 24 23:21:13 minidsp-shd systemd[1]: Started Music Player Daemon. Feb 24 23:21:13 minidsp-shd sudo[28816]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:13 minidsp-shd sudo[28804]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:13 minidsp-shd volumio[28526]: error: MPD error: The expression evaluated to a falsy value: Feb 24 23:21:13 minidsp-shd volumio[28526]: assert.ok(self.idling) Feb 24 23:21:13 minidsp-shd volumio[28526]: error: The expression evaluated to a falsy value: Feb 24 23:21:13 minidsp-shd volumio[28526]: assert.ok(self.idling) Feb 24 23:21:13 minidsp-shd volumio[28526]: info: MPD running with PID28819 Feb 24 23:21:13 minidsp-shd volumio[28526]: ,establishing connection Feb 24 23:21:13 minidsp-shd volumio[28526]: error: updateQueue error: null Feb 24 23:21:13 minidsp-shd volumio[28526]: info: Executing endpoint tc_getconfig Feb 24 23:21:13 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Feb 24 23:21:13 minidsp-shd vtcs[28935]: STARTING TidalConnect services, version: 1.3.0.19 Feb 24 23:21:13 minidsp-shd volumio[28526]: error: updateQueue error: null Feb 24 23:21:13 minidsp-shd volumio[28526]: info: MRS: Getting audio outputs on start Feb 24 23:21:13 minidsp-shd volumio[28526]: info: MRS: Requesting all other devices output Feb 24 23:21:14 minidsp-shd volumio[28526]: SPOTIFY: User informations: {"country":"DE","display_name":"saschabies80","email":"saschabies80@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/saschabies80"},"followers":{"href":null,"total":2},"href":"https://api.spotify.com/v1/users/saschabies80","id":"saschabies80","images":[],"product":"premium","type":"user","uri":"spotify:user:saschabies80"} Feb 24 23:21:14 minidsp-shd volumio[28526]: info: Spotify Successfully logged in Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 24 23:21:14 minidsp-shd volumio[28526]: info: [1740435674019] CoreMusicLibrary::Adding element Spotify Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source Calm Radio Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source YouTube Music Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source 80s80s Radio Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source Presets Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source QOBUZ Feb 24 23:21:14 minidsp-shd volumio[28526]: Cannot find translation for source Spotify Feb 24 23:21:14 minidsp-shd volumio[28526]: info: go-librespot daemon successfully initialized Feb 24 23:21:14 minidsp-shd vtcs[28935]: STARTED TidalConnect services. Feb 24 23:21:14 minidsp-shd volumio[28526]: info: Executing endpoint tc_connect Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Feb 24 23:21:14 minidsp-shd volumio[28526]: info: Connecting to TidalConnect Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::servicePushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:14 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:21:14] [connect] Successful connection Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:14 minidsp-shd volumio[28526]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received tidalconnect Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::servicePushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CorePlayQueue::getTrack 0 Feb 24 23:21:14 minidsp-shd volumio[28526]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received tidalconnect Feb 24 23:21:14 minidsp-shd volumio-remote-updater[459]: [2025-02-24 23:21:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1740435674 101 Feb 24 23:21:14 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 4 Feb 24 23:21:14 minidsp-shd volumio[28526]: info: msSurfaceDial volumioupdatevolume callback: {"vol":100,"dbVolume":0,"mute":false,"disableVolumeControl":false} Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:14 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Feb 24 23:21:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:14 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2373. Feb 24 23:21:14 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:14 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:14 minidsp-shd go-librespot[28958]: Librespot-go daemon starting... Feb 24 23:21:14 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:14+01:00" level=info msg="generated new device id: 5b9f8e8473555aae536120ca51eeb3753dd9e5ac" Feb 24 23:21:14 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:14+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="zeroconf server listening on port 41891" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="obtained new client token: AACe4Po4lJaxFPcZjCvwnwi4DKGfvHtbbk2o7xqVT6mP2K1D0eT0CQNeDJzO1LDBmJPSk2mtF1fHfq7iXnk+X0p7GcjNtxtsG5PiTDQQiQAW6+sBfWTHqrvvlXhds5Z/dSDQ8b9aHUDEWyrXn06wiXxnMSE+Zr26lFFP560rKJEM6VmNDKEqu2j32NOz927CeYQ3a2+6USzrei0OffN4Q78tkj698A/3gzqLWRPJad1XdkI4U+Ctb09DJ4w=" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=debug msg="completed challenge" Feb 24 23:21:15 minidsp-shd go-librespot[28958]: time="2025-02-24T23:21:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:15 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:16 minidsp-shd volumio[28526]: info: TidalConnect service started! Feb 24 23:21:16 minidsp-shd volumio[28526]: info: Completed starting Core Plugins Feb 24 23:21:16 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:21:16 minidsp-shd volumio[28526]: info: ----- MyVolumio plugins startup ---- Feb 24 23:21:16 minidsp-shd volumio[28526]: info: ------------------------------------------- Feb 24 23:21:16 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 24 23:21:17 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:17 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 24 23:21:18 minidsp-shd volumio[28526]: info: Not Reporting Auto name since its the default one Feb 24 23:21:18 minidsp-shd volumio[28526]: info: RAAT Overriding default device vendor model Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Feb 24 23:21:18 minidsp-shd volumio[28526]: xcb_connection_has_error() returned true Feb 24 23:21:18 minidsp-shd sudo[28974]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Feb 24 23:21:18 minidsp-shd sudo[28974]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:18 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Feb 24 23:21:18 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Feb 24 23:21:18 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Feb 24 23:21:18 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Feb 24 23:21:18 minidsp-shd systemd[1]: Started RAAT DAEMON. Feb 24 23:21:18 minidsp-shd volumio[28526]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 24 23:21:18 minidsp-shd volumio[28526]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 24 23:21:18 minidsp-shd sudo[28974]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:18 minidsp-shd volumio[28526]: info: Raat Daemon started successfully Feb 24 23:21:18 minidsp-shd volumio[28526]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 24 23:21:18 minidsp-shd volumio[28526]: info: Executing endpoint restartRAATSocket Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Feb 24 23:21:18 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Feb 24 23:21:18 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:18 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2374. Feb 24 23:21:18 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:19 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:19 minidsp-shd go-librespot[28987]: Librespot-go daemon starting... Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=info msg="generated new device id: f1ce48096d2b46c12c02b2df91e027f172f33904" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:19 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Feb 24 23:21:19 minidsp-shd volumio[28526]: info: updateDSP function in raat called! Feb 24 23:21:19 minidsp-shd volumio[28526]: info: Updating RAAT Signal Path Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="zeroconf server listening on port 43105" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="obtained new client token: AAATJjlP/e4W/AiGPoH1gYu6AfqaJGG728SmjSTel/CW9UOrCS7Aimb8iwa7iedyRCUNCep56ZMlUBsXoFo+ofz+dnn136u4mno+ppKcCBuzYr1PxVI7haE5QIgoRyhJqRVLlNXt3NrdMA+AKtoLuFvh/rxcnrleSYKfAJ/MILrGpAjytQB43b09MSZHiq5cryrx9WDVl72VqmwZG4Z7IgH+AiK9dFfbjLUdehICpzSJ7Hn/VJNYrc6gwsYw7w==" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:19 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:19+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:20 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:20 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:20+01:00" level=debug msg="new websocket client" Feb 24 23:21:20 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:20+01:00" level=debug msg="completed challenge" Feb 24 23:21:20 minidsp-shd volumio[28526]: info: Connection to go-librespot Websocket established Feb 24 23:21:20 minidsp-shd go-librespot[28987]: time="2025-02-24T23:21:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:20 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:20 minidsp-shd volumio[28526]: info: Connection to go-librespot Websocket closed Feb 24 23:21:23 minidsp-shd volumio[28526]: info: Getting Spotify volume Feb 24 23:21:23 minidsp-shd volumio[28526]: (node:28526) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:23 minidsp-shd volumio[28526]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 23:21:23 minidsp-shd volumio[28526]: (node:28526) 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: 1) Feb 24 23:21:23 minidsp-shd volumio[28526]: (node:28526) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Feb 24 23:21:23 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Feb 24 23:21:23 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:23 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2375. Feb 24 23:21:23 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:23 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:23 minidsp-shd go-librespot[28995]: Librespot-go daemon starting... Feb 24 23:21:23 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=info msg="generated new device id: c155b97135a4844e4fbb4586d4b82caea5bc401a" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:23 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:23 minidsp-shd volumio[28526]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 23:21:23 minidsp-shd volumio[28526]: SPOTIFY: SPOTIFY VOLUME undefined Feb 24 23:21:23 minidsp-shd volumio[28526]: SPOTIFY: VOLUMIO VOLUME 100 Feb 24 23:21:23 minidsp-shd volumio[28526]: info: Aligning Spotify Volume to Volumio Volume Feb 24 23:21:23 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:23 minidsp-shd volumio[28526]: info: Setting Spotify Volume from Volumio: 100 Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="zeroconf server listening on port 37307" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="obtained new client token: AAC9+5MEQNkg7873BMl1EWhuV7LMer+RSGEQGV1zYOSclVbPcotKspo7IEV+v9HgEvYKJrHe991Gha09DhDDOxwDIMiQm9GEVs4LlJ7ZeSIO7qxJUydWaBmEaAgdDkPCaEOlVVXczyBvQhZo2MXr8AX4ZrUjTZSztOrfqlxNEHa0OeQq5n5ZRL6L753Z3oNpHdOXyPoqmthjaU72GEfZ1LSy8XejbcDfYgMCh6jiu0VWjomdmB07q5yFFhwPeA==" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:23 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:23+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:24 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:24+01:00" level=debug msg="completed challenge" Feb 24 23:21:24 minidsp-shd go-librespot[28995]: time="2025-02-24T23:21:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:24 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 24 23:21:24 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 24 23:21:26 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 24 23:21:26 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:26 minidsp-shd volumio[28526]: info: Starting MyVolumio Remote Streaming Endpoints Feb 24 23:21:26 minidsp-shd volumio[28526]: info: MyVolumio login type: Token Feb 24 23:21:26 minidsp-shd volumio[28526]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 24 23:21:26 minidsp-shd volumio[28526]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' Feb 24 23:21:26 minidsp-shd volumio[28526]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Feb 24 23:21:26 minidsp-shd volumio[28526]: info: Sending Spotify command with payload to local API: /player/volume Feb 24 23:21:26 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:26 minidsp-shd volumio[28526]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:26 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:21:26 minidsp-shd volumio[28526]: info: Discovery: Getting this device information Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:21:26 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to 192.168.1.27:3000 from 192.168.1.217 UA: Dart/3.5 (dart:io) Total Clients: 6 Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 24 23:21:26 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 24 23:21:26 minidsp-shd volumio[28526]: error: MyVolumio Custom Token format not valid, refreshing it Feb 24 23:21:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:27 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2376. Feb 24 23:21:27 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:27 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:27 minidsp-shd go-librespot[29004]: Librespot-go daemon starting... Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=info msg="generated new device id: 8fca210df05069b7d19c1c9b6abad142d24736e7" Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:27 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:21:27 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:21:27 minidsp-shd volumio[28526]: info: Discovery: Getting this device information Feb 24 23:21:27 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:27 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:21:27 minidsp-shd volumio[28526]: info: MyVolumio login type: Token Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:27 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:27+01:00" level=debug msg="zeroconf server listening on port 38527" Feb 24 23:21:28 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:28+01:00" level=debug msg="obtained new client token: AABoIrdb6B/hPXlZfMiiyN3ugTCM/mzLyxIVkoB/8XsDCD5RLq0jPMgA1ZTz+e9YW9sSGZRo5YEQ0bXVnG5ps9GbPv33bP/0UsA/rxY12nwik2CdsJw+/OvdjBvSHJx7X5CokP/jNIhSUXGgXxlLZQGG59RUV8es9a3+b2o3Aei61BlhAPh5H0Mhdp0UFcuP2+vb+DdVcXQFBvRYOHMMeOB3XCiUemeV/ucyyCCVHV3d0MMak/i3iEG7SDE=" Feb 24 23:21:28 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:28+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:28 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:28+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:28 minidsp-shd volumio[28526]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 24 23:21:28 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:28+01:00" level=debug msg="completed challenge" Feb 24 23:21:28 minidsp-shd go-librespot[29004]: time="2025-02-24T23:21:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:28 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:29 minidsp-shd volumio[28526]: info: MyVolumio token set successfully Feb 24 23:21:29 minidsp-shd volumio[28526]: info: MYVOLUMIO: Adding device Feb 24 23:21:29 minidsp-shd volumio[28526]: info: MYVOLUMIO: Evaluating Server Feb 24 23:21:29 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:29 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:30 minidsp-shd volumio[28526]: info: MyVolumio status changed Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Streaming services startup Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Starting Streaming Daemon Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Removing browser output: myVolumio user plan is not superstar Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Removing audio output: Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Stoppping Tunnel 1 Feb 24 23:21:30 minidsp-shd sudo[29030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 24 23:21:30 minidsp-shd sudo[29030]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:30 minidsp-shd sudo[29030]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:30 minidsp-shd sudo[29033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Feb 24 23:21:30 minidsp-shd sudo[29033]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:30 minidsp-shd volumio[28526]: error: Cannot start Volumio Streaming Daemon Feb 24 23:21:30 minidsp-shd volumio[28526]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 24 23:21:30 minidsp-shd volumio[28526]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 24 23:21:30 minidsp-shd sudo[29033]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:30 minidsp-shd volumio[28526]: info: Remote SSH Stopped Feb 24 23:21:31 minidsp-shd sudo[29036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:21:31 minidsp-shd sudo[29036]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:31 minidsp-shd sudo[29036]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:31 minidsp-shd sudo[29039]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:21:31 minidsp-shd sudo[29039]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:31 minidsp-shd sudo[29039]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:31 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2377. Feb 24 23:21:31 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:31 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:32 minidsp-shd go-librespot[29043]: Librespot-go daemon starting... Feb 24 23:21:32 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 7 Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=info msg="generated new device id: 624d2b00ace96809eac47f31cce6d73d9fff443b" Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:32 minidsp-shd sudo[29052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:32 minidsp-shd sudo[29052]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="zeroconf server listening on port 33821" Feb 24 23:21:32 minidsp-shd sudo[29052]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:32 minidsp-shd sudo[29055]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 24 23:21:32 minidsp-shd sudo[29055]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 24 23:21:32 minidsp-shd sudo[29055]: pam_unix(sudo:session): session closed for user root Feb 24 23:21:32 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to 192.168.1.27 from 192.168.1.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 8 Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="obtained new client token: AADsxaVMwx+ZDBoSkQO3s/Froummpw3s+PM/S9sSHeYEq0jZtTtFp+YiQjg8ERQhL1recTHYfDCCM4NgK1vD3KKz2vObMzI0UtNQQhizxWVEmbB2j/MnTh6wipcq6nrGenPb7htyYI6VWvbUGgnezvcUBb5E67M/d4azrx4anrzq7m9fBDaYaTkIv+ktAA8yiGpcIfBiMb0Qbg9z0ezHXEUOJhRCunkezoH97tais0PeZdGEHN1GQ+nJRiuSdg==" Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="new websocket client" Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Connection to go-librespot Websocket established Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Setting Geolocation for MyVolumio to eu7 Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 24 23:21:32 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:32+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetVisibleSources Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Received Get System Info Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Discovery: Getting this device information Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:32 minidsp-shd volumio[28526]: info: Listing playlists Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 24 23:21:32 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 24 23:21:33 minidsp-shd volumio[28526]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Feb 24 23:21:33 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:33+01:00" level=debug msg="completed challenge" Feb 24 23:21:33 minidsp-shd go-librespot[29043]: time="2025-02-24T23:21:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:33 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:33 minidsp-shd volumio[28526]: info: Connection to go-librespot Websocket closed Feb 24 23:21:33 minidsp-shd volumio[28526]: info: Updating MyVolumio device info Feb 24 23:21:33 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:33 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:33 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:34 minidsp-shd volumio[28526]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Feb 24 23:21:34 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 24 23:21:34 minidsp-shd volumio[28526]: info: Received Get System Info Feb 24 23:21:34 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:21:34 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:21:34 minidsp-shd volumio[28526]: info: Discovery: Getting this device information Feb 24 23:21:34 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:34 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetQueue Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreStateMachine::getQueue Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CorePlayQueue::getQueue Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 24 23:21:35 minidsp-shd volumio[28526]: info: Received Get System Info Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:21:35 minidsp-shd volumio[28526]: info: Discovery: Getting this device information Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:21:35 minidsp-shd volumio[28526]: info: Getting Spotify volume Feb 24 23:21:35 minidsp-shd volumio[28526]: (node:28526) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:35 minidsp-shd volumio[28526]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Feb 24 23:21:35 minidsp-shd volumio[28526]: (node:28526) 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: 2) Feb 24 23:21:35 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 23:21:35 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:35 minidsp-shd volumio[28526]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 24 23:21:36 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:36 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:36 minidsp-shd volumio[28526]: error: MyVolumio Plugin failed to start in a timely fashion Feb 24 23:21:36 minidsp-shd volumio[28526]: info: BOOT COMPLETED Feb 24 23:21:36 minidsp-shd volumio[28526]: [Metrics] CommandRouter: 60s 456.42ms Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumiosetStartupVolume Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 23:21:36 minidsp-shd volumio[28526]: info: VolumeController:: Setting startup Volume 35 Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: inputs , setVolume Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::Close All Modals sent Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::Close All Modals sent Feb 24 23:21:36 minidsp-shd volumio[28526]: info: msSurfaceDial volumioupdatevolume callback: {"vol":35,"dbVolume":-83,"mute":false,"disableVolumeControl":false} Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreStateMachine::pushState Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 23:21:36 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioPushState Feb 24 23:21:36 minidsp-shd volumio[28526]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Feb 24 23:21:36 minidsp-shd volumio[28526]: SPOTIFY: SPOTIFY VOLUME 100 Feb 24 23:21:36 minidsp-shd volumio[28526]: SPOTIFY: VOLUMIO VOLUME 35 Feb 24 23:21:36 minidsp-shd volumio[28526]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 24 23:21:36 minidsp-shd volumio[28526]: info: Setting Spotify Volume from Volumio: 35 Feb 24 23:21:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:36 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2378. Feb 24 23:21:36 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:36 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:36 minidsp-shd go-librespot[29062]: Librespot-go daemon starting... Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=info msg="generated new device id: dc2be52bedcac7aa01cd7934ebb257a2d1392c2e" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="zeroconf server listening on port 36833" Feb 24 23:21:36 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:36+01:00" level=debug msg="obtained new client token: AAAclPrj0zwJgMyoEcY90fXZoouJkfC/+cQojI7PP323f0GPKiVQ0chkClwlWm+0qp0HUjzpKtKuX7ngEmb0s32eko2eCo3guwCNsoxDLXXtkI1ggZjvA0bb6BcLFHhERMyLoC5KbcDvh3/UEw6Z3Xj2QII+pjH3+kD1/B13fJTKgxErxvb9JOQCK8QVx0ZIdZjP19ra024hwRpKdXSMGHAKiyQwDD676D38bYJyH+/nRAiGu9T3Ka1pRGhgbQ==" Feb 24 23:21:37 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:37+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:37 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:37+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:37 minidsp-shd volumio[28526]: info: MYVOLUMIO: Adding device Feb 24 23:21:37 minidsp-shd volumio[28526]: info: MYVOLUMIO: Evaluating Server Feb 24 23:21:37 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:37+01:00" level=debug msg="completed challenge" Feb 24 23:21:37 minidsp-shd go-librespot[29062]: time="2025-02-24T23:21:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:37 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:38 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Feb 24 23:21:38 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 24 23:21:38 minidsp-shd volumio[28526]: xcb_connection_has_error() returned true Feb 24 23:21:38 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Feb 24 23:21:38 minidsp-shd volumio[28526]: SPOTIFY: SETTING SPOTIFY VOLUME 35 Feb 24 23:21:38 minidsp-shd volumio[28526]: info: Sending Spotify command with payload to local API: /player/volume Feb 24 23:21:38 minidsp-shd volumio[28526]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:39 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:39 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 24 23:21:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 24 23:21:39 minidsp-shd volumio-remote-updater[459]: No test mode Feb 24 23:21:39 minidsp-shd volumio-remote-updater[459]: No alpha test mode Feb 24 23:21:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 24 23:21:39 minidsp-shd volumio[28526]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 24 23:21:39 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 24 23:21:40 minidsp-shd volumio[28526]: info: Setting Geolocation for MyVolumio to eu9 Feb 24 23:21:40 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:40 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:40 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:40 minidsp-shd volumio[28526]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Feb 24 23:21:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 23:21:40 minidsp-shd systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2379. Feb 24 23:21:40 minidsp-shd systemd[1]: Stopped go-librespot Daemon. Feb 24 23:21:40 minidsp-shd systemd[1]: Started go-librespot Daemon. Feb 24 23:21:40 minidsp-shd go-librespot[29091]: Librespot-go daemon starting... Feb 24 23:21:40 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:40+01:00" level=info msg="generated new device id: 7f495ccaf5fa19eba68e0b072e206fe7661bda25" Feb 24 23:21:40 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:40+01:00" level=debug msg="stored credentials found for saschabies80" Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 24 23:21:41 minidsp-shd volumio[28526]: info: Updating MyVolumio device info Feb 24 23:21:41 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:41 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:41 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="zeroconf server listening on port 42555" Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="obtained new client token: AAA1jNuzT/WCeRSUy9lfjVS/Eiczgxx6b1eFf08HDh0qo6hXwD/qPAsZzOlmgwnfHIMyxdqqSTjWMWPV9eYxnACnxEdBkvYmNPMhENGgWAg0Lf41ZlFX4SngCOO8BS1Mu8gd1z5psxydJf0dPfnIj1JtKbFmGO3wIFtl9H81NzoTqiKWnqCXhaBKoj3o5FrqyM192ZfpNVjku39Ph1YZ3joR+q4Sk50YBh7Ox689FQN8d4mBj4YcZN/qmCw=" Feb 24 23:21:41 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 24 23:21:41 minidsp-shd volumio[28526]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="completed keyexchange" Feb 24 23:21:41 minidsp-shd volumio[28526]: info: CoreCommandRouter::volumioGetState Feb 24 23:21:41 minidsp-shd volumio[28526]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=debug msg="completed challenge" Feb 24 23:21:41 minidsp-shd go-librespot[29091]: time="2025-02-24T23:21:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Feb 24 23:21:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 23:21:41 minidsp-shd systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 23:21:42 minidsp-shd volumio[28526]: info: Initializing connection to go-librespot Websocket Feb 24 23:21:42 minidsp-shd volumio[28526]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 23:21:43 minidsp-shd volumio[28526]: Searching all installed plugins Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: webradio , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Feb 24 23:21:43 minidsp-shd volumio[28526]: info: [1740435703302] ControllerCalmRadio::searchCategories Feb 24 23:21:43 minidsp-shd volumio[28526]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:21:43 minidsp-shd volumio[28526]: TypeError: Cannot read property 'cats' of undefined Feb 24 23:21:43 minidsp-shd volumio[28526]: at ControllerCalmRadio.searchCategories (/data/plugins/music_service/calmradio/index.js:615:42) Feb 24 23:21:43 minidsp-shd volumio[28526]: at ControllerCalmRadio.search (/data/plugins/music_service/calmradio/index.js:665:28) Feb 24 23:21:43 minidsp-shd volumio[28526]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Feb 24 23:21:43 minidsp-shd volumio[28526]: at CoreMusicLibrary.searchOnPlugin (/volumio/app/musiclibrary.js:668:44) Feb 24 23:21:43 minidsp-shd volumio[28526]: at CoreMusicLibrary.search (/volumio/app/musiclibrary.js:455:27) Feb 24 23:21:43 minidsp-shd volumio[28526]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:457:44) Feb 24 23:21:43 minidsp-shd volumio[28526]: at Socket.emit (events.js:400:28) Feb 24 23:21:43 minidsp-shd volumio[28526]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 24 23:21:43 minidsp-shd volumio[28526]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Feb 24 23:21:43 minidsp-shd volumio[28526]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:21:44 minidsp-shd sudo[29109]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 23:20 Feb 24 23:21:44 minidsp-shd sudo[29109]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:13:25 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo3" VOLUMIO_DEVICENAME="Nanopi Neo3" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="18533ba33f8f92d7e7e459bb30f70beb"