-- Logs begin at Thu 2025-01-16 19:10:41 CET, end at Thu 2025-01-16 19:15:43 CET. -- Jan 16 19:14:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Jan 16 19:14:00 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:00 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:00 volumio go-librespot[3128]: Librespot-go daemon starting... Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=info msg="generated new device id: 56be5b959df34093fb0ebea2b67ec3c895bccbd2" Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=debug msg="obtained new client token: AACEv7YkiRPMUPREBqm3MeqlscveB99vXNx0JP81xKzG2c3zDwXCBtXdryaUUwPJWbzlkzH44DIlUvMeVnLKgEAWvKEu5w3MVdzRTX/xbcvInypB5cAqmdFOZC0LowcfyjF8ttJheydN+uakJ2kAyydshJqGWjkRgV4tv4nBhDwuXEX985CUXQyzr709L8gSI/uT0BWSrN8ofPD1jDGmn+hFQbavU/c7v4+KBoUDgmy5jjR9090gl+AHFew=" Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: Jan 16 19:14:00 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:14:00 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14:00+01:00" level=debug msg="completed challenge" Jan 16 19:14:00 volumio go-librespot[3128]: time="2025-01-16T19:14: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" Jan 16 19:14:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:01 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:01 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Jan 16 19:14:04 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:04 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:04 volumio go-librespot[3148]: Librespot-go daemon starting... Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=info msg="generated new device id: 5d6bf6015d6959d310de33eb6d18904345527a9e" Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="obtained new client token: AABt9oLsOyOex0oWJtF6EWP9VKO+SpDFl3MEpPvn61u1CnSo+56xBlj4ZbzVARHfq6doWESaXkq4Wp7K/hbMN8T4MGXGU5J9ehJK1Q7yYwHqzsLA3iwCzmo+qjsygUB6tb2HA7DiAy7J9tsbWVkeLP1kMbHXtHeHyTItii6nZKhrN4YA5o7KNIc9BaEGEYH/T0Kygd3rvP04iGAuRLAuSlRipXfV/i2U2fJxj8AksWXOtfC0Kt7NQACwSF4=" Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:04 volumio sudo[3162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 16 19:14:04 volumio sudo[3162]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:04 volumio sudo[3162]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:04 volumio sudo[3165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 16 19:14:04 volumio sudo[3165]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:04 volumio sudo[3165]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:04 volumio volumio[815]: verbose: New Socket.io Connection to 192.168.1.16 from 192.168.1.22 UA: Mozilla/5.0 (Linux; Android 10; CLT-L29 Build/HUAWEICLT-L29; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.201 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="completed challenge" Jan 16 19:14:04 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14:04+01:00" level=debug msg="new websocket client" Jan 16 19:14:04 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:14:04 volumio go-librespot[3148]: time="2025-01-16T19:14: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" Jan 16 19:14:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:04 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:14:05 volumio sudo[3170]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 16 19:14:05 volumio sudo[3170]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:05 volumio sudo[3170]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:05 volumio sudo[3173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 16 19:14:05 volumio sudo[3173]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:05 volumio sudo[3173]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:05 volumio volumio[815]: verbose: New Socket.io Connection to 192.168.1.16 from 192.168.1.22 UA: Mozilla/5.0 (Linux; Android 10; CLT-L29 Build/HUAWEICLT-L29; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.201 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::volumioGetVisibleSources Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 16 19:14:05 volumio volumio[815]: info: Received Get System Info Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:05 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:05 volumio volumio[815]: info: Listing playlists Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 16 19:14:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 16 19:14:07 volumio volumio[815]: info: Received Get System Info Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:07 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 16 19:14:07 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:14:07 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:07 volumio volumio[815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jan 16 19:14:07 volumio volumio[815]: (node:815) 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: 11) Jan 16 19:14:07 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 16 19:14:07 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:07 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:07 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:07 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Jan 16 19:14:08 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:08 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:08 volumio go-librespot[3198]: Librespot-go daemon starting... Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=info msg="generated new device id: 8cdada2f933ef954197be40989e04d487f3a13ec" Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=debug msg="obtained new client token: AADYX4nvA0XCWhtyQqwkNkGABpsU6XyTNMPQeTLq8jol2GCtZfywFwR2rgm0XjvYffwuSs84CJFLjfdJMyLxrSGYCx2ldOF1oT0khni46dp7mPTHa4CQwaFDcy3jKbpHHhG7gyCxJcyfLejCsUTyvzyMjBn75djapZYCu/wEUS0Xyq3G33z9cA4Y/7QECNZrP582+N7tXB/puUM4zVRO1zb7kXfGsAzJrBbUoGq9blaosAWBsV6baWGwtJM=" Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: info: Retrieving Cloud Streaming UI Jan 16 19:14:08 volumio volumio[815]: info: Getting Tidal Cloud Configuration Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: info: Getting Qobuz Cloud Configuration Jan 16 19:14:08 volumio volumio[815]: info: Asking plugin for UI Config Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: info: Getting Spotify Cloud Configuration Jan 16 19:14:08 volumio volumio[815]: info: Asking plugin for UI Config Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: info: Saving Spotify Acccount Jan 16 19:14:08 volumio volumio[815]: info: Got Tidal Cloud Configuration Jan 16 19:14:08 volumio volumio[815]: info: Got it Jan 16 19:14:08 volumio volumio[815]: info: Got it Jan 16 19:14:08 volumio volumio[815]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:14:08 volumio volumio[815]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::volumioGetBrowseSources Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::volumioGetBrowseSources Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::volumioGetBrowseSources Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 16 19:14:08 volumio volumio[815]: info: Received Get System Info Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:08 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:08 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14:08+01:00" level=debug msg="completed challenge" Jan 16 19:14:08 volumio go-librespot[3198]: time="2025-01-16T19:14: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" Jan 16 19:14:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:10 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:10 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:11 volumio volumio[815]: info: Disabling MyMusic plugin upnp Jan 16 19:14:11 volumio sudo[3213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jan 16 19:14:11 volumio sudo[3213]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:11 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Jan 16 19:14:11 volumio systemd[1]: upmpdcli.service: Succeeded. Jan 16 19:14:11 volumio systemd[1]: Stopped UPnP Renderer front-end to MPD. Jan 16 19:14:11 volumio sudo[3213]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:11 volumio volumio[815]: info: Disabling plugin upnp Jan 16 19:14:11 volumio volumio[815]: info: Done. Jan 16 19:14:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51. Jan 16 19:14:12 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:12 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:12 volumio go-librespot[3215]: Librespot-go daemon starting... Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=info msg="generated new device id: 486e62e3a6951ef7fa416e53429fb408c6a53923" Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=debug msg="obtained new client token: AACWpTxkHZkpfDEDZs5SkVK7R+7hRInCZMmIuVsT4UqFeorI4+3nNM2QTtq8DlpEIADq/dutQ+HTPY6Gtg3vL8T0Oe0LhR1fbtVB0YrkF68bCup9HVBprnl9Qd8ameRDMVb326HGYloUjP1g1s4kgQMP1epYMsiPcxbfHKrRQiILPIEyO4QxDuzikedac6qj3+zoK7Z0So/16ari5sVdQeXsyrgbrKVajAcFC/OkCdbBpBDgg4kNP60n8Fs=" Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:12 volumio volumio[815]: info: Enabling MyMusic plugin upnp Jan 16 19:14:12 volumio volumio[815]: info: Enabling plugin upnp Jan 16 19:14:12 volumio volumio[815]: info: Loading plugin "upnp"... Jan 16 19:14:12 volumio volumio[815]: info: [1737051252824] Starting Upmpd Daemon Jan 16 19:14:12 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 16 19:14:12 volumio volumio[815]: info: Done. Jan 16 19:14:12 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=debug msg="completed challenge" Jan 16 19:14:12 volumio go-librespot[3215]: time="2025-01-16T19:14:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:13 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:13 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:14 volumio volumio[815]: info: Disabling MyMusic plugin upnp Jan 16 19:14:14 volumio sudo[3225]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jan 16 19:14:14 volumio sudo[3225]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:14 volumio sudo[3225]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:14 volumio volumio[815]: info: Disabling plugin upnp Jan 16 19:14:14 volumio volumio[815]: info: Done. Jan 16 19:14:14 volumio volumio[815]: info: Enabling MyMusic plugin upnp Jan 16 19:14:14 volumio volumio[815]: info: Enabling plugin upnp Jan 16 19:14:14 volumio volumio[815]: info: Loading plugin "upnp"... Jan 16 19:14:14 volumio volumio[815]: info: [1737051254849] Starting Upmpd Daemon Jan 16 19:14:14 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 16 19:14:14 volumio volumio[815]: info: Done. Jan 16 19:14:15 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 16 19:14:16 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52. Jan 16 19:14:16 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:16 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:16 volumio go-librespot[3244]: Librespot-go daemon starting... Jan 16 19:14:16 volumio go-librespot[3244]: time="2025-01-16T19:14:16+01:00" level=info msg="generated new device id: 79d6c2733579e7434458c5570790461a5fde625c" Jan 16 19:14:16 volumio go-librespot[3244]: time="2025-01-16T19:14:16+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:16 volumio go-librespot[3244]: time="2025-01-16T19:14:16+01:00" level=debug msg="obtained new client token: AADSXy8kDPPuwlbJkZTuScy836gInseIQu1Y2wvhhjj4YOrwFAd3L2yAI1k2aKjI34XRd9rZAk7IH6JttGN9CTrZts2RGCvHajvwBMf+cp3v6znKI5hMQzmYGaQexIIuqlW1X7W83FkeD2hHppGXqtCRI7JNohDuSqww3wkm/Ixk79LEm6L8hNH37wOyKrFa3poCD1YCiZOihxyalveKAyCCbA0VPdAl5cX87YccIdZZ634EQ3hPoemsaPU=" Jan 16 19:14:16 volumio go-librespot[3244]: time="2025-01-16T19:14:16+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 16 19:14:16 volumio go-librespot[3244]: time="2025-01-16T19:14:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.9:4070: connect: connection refused" Jan 16 19:14:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:16 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:16 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:17 volumio volumio[815]: info: Disabling MyMusic plugin upnp_browser Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesServeurs Média Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 16 19:14:17 volumio volumio[815]: info: Disabling plugin upnp_browser Jan 16 19:14:17 volumio volumio[815]: info: Done. Jan 16 19:14:17 volumio volumio[815]: info: Enabling MyMusic plugin upnp_browser Jan 16 19:14:17 volumio volumio[815]: info: Enabling plugin upnp_browser Jan 16 19:14:17 volumio volumio[815]: info: Loading plugin "upnp_browser"... Jan 16 19:14:17 volumio volumio[815]: info: PLUGIN START: upnp_browser Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 16 19:14:17 volumio volumio[815]: info: [1737051257677] CoreMusicLibrary::Adding element Serveurs Média Jan 16 19:14:17 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 16 19:14:17 volumio volumio[815]: info: Done. Jan 16 19:14:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53. Jan 16 19:14:19 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:19 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:19 volumio go-librespot[3252]: Librespot-go daemon starting... Jan 16 19:14:19 volumio go-librespot[3252]: time="2025-01-16T19:14:19+01:00" level=info msg="generated new device id: e4e14bfe9f7a219e29cbde3bb63d8c8af9c12126" Jan 16 19:14:19 volumio go-librespot[3252]: time="2025-01-16T19:14:19+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:19 volumio go-librespot[3252]: time="2025-01-16T19:14:19+01:00" level=debug msg="obtained new client token: AABZGuY5WVxBSodGvyE0YACRDtaLzh3WtKbTMPLNw2WOI9bvLPw8xe9KdZowCbWRLE2V3p9jkTAWX7GACX3urMAwBRS2l6zgtVDnFa19/htrEm8rAMDkDWYUA0GUjrOAw6cU9lAp+krzfOB0m2hLCdueTaSx47JeAc8Mm4j5fVJ+b18CN8N/o4rjLuAhYKSbB6yXoGB7LdaN7ucM6WJGiYutF2uyf5LNiHtd5U0DIs2gNbytOxfe9qbDAXEXVw==" Jan 16 19:14:19 volumio go-librespot[3252]: time="2025-01-16T19:14:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 16 19:14:19 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:19 volumio go-librespot[3252]: time="2025-01-16T19:14:19+01:00" level=debug msg="new websocket client" Jan 16 19:14:19 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:14:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:20 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:20 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:22 volumio go-librespot[3252]: time="2025-01-16T19:14:22+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:22 volumio sudo[3261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 16 19:14:22 volumio sudo[3261]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:22 volumio sudo[3261]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:22 volumio sudo[3264]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 16 19:14:22 volumio sudo[3264]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:22 volumio sudo[3264]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:22 volumio sudo[3268]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 16 19:14:22 volumio sudo[3268]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:22 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jan 16 19:14:22 volumio sudo[3268]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:22 volumio volumio[815]: info: Upmpdcli Daemon Started Jan 16 19:14:22 volumio volumio[3271]: writing RSA key Jan 16 19:14:22 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:14:22 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 16 19:14:22 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:22 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:23 volumio go-librespot[3252]: time="2025-01-16T19:14:23+01:00" level=debug msg="completed challenge" Jan 16 19:14:23 volumio go-librespot[3252]: time="2025-01-16T19:14:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:23 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: socket hang up Jan 16 19:14:23 volumio volumio[815]: at connResetException (internal/errors.js:639:14) Jan 16 19:14:23 volumio volumio[815]: at Socket.socketOnEnd (_http_client.js:499:23) Jan 16 19:14:23 volumio volumio[815]: at Socket.emit (events.js:412:35) Jan 16 19:14:23 volumio volumio[815]: at endReadableNT (internal/streams/readable.js:1333:12) Jan 16 19:14:23 volumio volumio[815]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jan 16 19:14:23 volumio volumio[815]: (node:815) 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: 12) Jan 16 19:14:23 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 16 19:14:23 volumio volumio[815]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jan 16 19:14:23 volumio volumio[815]: info: Received Get System Version Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 16 19:14:23 volumio volumio[815]: info: Received Get System Info Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:23 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:23 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:24 volumio sudo[3310]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 16 19:14:24 volumio sudo[3310]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:24 volumio sudo[3310]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:24 volumio sudo[3313]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 16 19:14:24 volumio sudo[3313]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:24 volumio sudo[3313]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:24 volumio sudo[3317]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 16 19:14:24 volumio sudo[3317]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:14:24 volumio sudo[3317]: pam_unix(sudo:session): session closed for user root Jan 16 19:14:24 volumio volumio[815]: info: Upmpdcli Daemon Started Jan 16 19:14:26 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:26 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:26 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54. Jan 16 19:14:26 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:26 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:26 volumio go-librespot[3339]: Librespot-go daemon starting... Jan 16 19:14:26 volumio go-librespot[3339]: time="2025-01-16T19:14:26+01:00" level=info msg="generated new device id: 104a21e7f461d48d72450c1798d17330cc0416a7" Jan 16 19:14:26 volumio go-librespot[3339]: time="2025-01-16T19:14:26+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:26 volumio go-librespot[3339]: time="2025-01-16T19:14:26+01:00" level=debug msg="obtained new client token: AADZVgmDzz2k9OhuehydQKRg6yN7SB457BjUtxK3VQCeUxl28atcUtzS7+hzdPRi0gNxL8Lrn1w8R6xtZ5fpO9lZME6bxSqmQ1paOQByJSNQ3snhyMyScIdo3Z/QHU5b11oGyEWrt/FJr0z6uHhi8qbi47dZiAxe0b1dANZ4UpEQhF1duCzrak+MLSAq0lx44L4mHYRxdpG7paB6WTgXx/aWKDZ8OWbmobq6QNZdM6bUED6/6aEY6Rdnoe9LLg==" Jan 16 19:14:27 volumio go-librespot[3339]: time="2025-01-16T19:14:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:27 volumio go-librespot[3339]: time="2025-01-16T19:14:27+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:27 volumio go-librespot[3339]: time="2025-01-16T19:14:27+01:00" level=debug msg="completed challenge" Jan 16 19:14:27 volumio go-librespot[3339]: time="2025-01-16T19:14: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" Jan 16 19:14:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:29 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:29 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:29 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. Jan 16 19:14:30 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:30 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:30 volumio go-librespot[3355]: Librespot-go daemon starting... Jan 16 19:14:30 volumio go-librespot[3355]: time="2025-01-16T19:14:30+01:00" level=info msg="generated new device id: 8d644561cf1942a6e534516d038cb0421f29841e" Jan 16 19:14:30 volumio go-librespot[3355]: time="2025-01-16T19:14:30+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:30 volumio go-librespot[3355]: time="2025-01-16T19:14:30+01:00" level=debug msg="obtained new client token: AAA09xoiNkgyrbS1fgvvOpoDViKRJtdMZNVr9VrkE1evulU+9yrXycD5rSqmjGM29DndDXUIPucwgZt+BRiL9SzjymFaiVBfm3zwTxTWDoHXoGnfj8xstZoCGlFyeGaolNwSnTxvb828uazOYEkNa8hda43nZ4PkVfo9nuo0lj27VMk9ILv9iNA/SlqYPI+1t3VBuCvKFBWArVwyiV3s+KrzlOwJsmhbAJwCVvdhMESqLZWD/zlB0NcK10bozQ==" Jan 16 19:14:31 volumio go-librespot[3355]: time="2025-01-16T19:14:31+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:31 volumio go-librespot[3355]: time="2025-01-16T19:14:31+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:31 volumio go-librespot[3355]: time="2025-01-16T19:14:31+01:00" level=debug msg="completed challenge" Jan 16 19:14:31 volumio go-librespot[3355]: time="2025-01-16T19:14:31+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:32 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:32 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:33 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Jan 16 19:14:34 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:34 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:34 volumio go-librespot[3374]: Librespot-go daemon starting... Jan 16 19:14:34 volumio go-librespot[3374]: time="2025-01-16T19:14:34+01:00" level=info msg="generated new device id: 25491d3031fe235038bfd11f296d3ce6830763b6" Jan 16 19:14:34 volumio go-librespot[3374]: time="2025-01-16T19:14:34+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:34 volumio go-librespot[3374]: time="2025-01-16T19:14:34+01:00" level=debug msg="obtained new client token: AABsPx8SsS9mfoMCjIoJ7LAUIj9fa1N7jAaCzcN36osKxRK0BBLNSl50h44jCDBST+vGvZuD8JtqmWdNCjc5FkSt8RG3+6iPr1qfrAVqFKaIpbuUx56YxlbN4gVdBMIFufBXE2MB1EuxxQU3D4kdciyA6BAQTX7V4Og+wQ15t5puha47xOchLj2mfGMnPBXazvYONykgkptsHFfFoRgbx3RXNtVy10wJVubWD7q8GxyoudiFZGJCyL2nHQJN9g==" Jan 16 19:14:35 volumio go-librespot[3374]: time="2025-01-16T19:14:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:35 volumio go-librespot[3374]: time="2025-01-16T19:14:35+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:35 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:35 volumio go-librespot[3374]: time="2025-01-16T19:14:35+01:00" level=debug msg="new websocket client" Jan 16 19:14:35 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:14:35 volumio go-librespot[3374]: time="2025-01-16T19:14:35+01:00" level=debug msg="completed challenge" Jan 16 19:14:35 volumio go-librespot[3374]: time="2025-01-16T19:14:35+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:35 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:14:38 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:14:38 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:38 volumio volumio[815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jan 16 19:14:38 volumio volumio[815]: (node:815) 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: 13) Jan 16 19:14:38 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 16 19:14:38 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:38 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:38 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:38 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Jan 16 19:14:38 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:38 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:38 volumio go-librespot[3405]: Librespot-go daemon starting... Jan 16 19:14:38 volumio go-librespot[3405]: time="2025-01-16T19:14:38+01:00" level=info msg="generated new device id: 10cd03f85cada561e2f340aabd4ae0898fe106b1" Jan 16 19:14:38 volumio go-librespot[3405]: time="2025-01-16T19:14:38+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:38 volumio go-librespot[3405]: time="2025-01-16T19:14:38+01:00" level=debug msg="obtained new client token: AAB/pcZteN1pFaSGVnxDhcktMYwHsfikdqqml89rrnevWu5vzm7jjCLz4pvQiJZRf9syrsCVtANa9VJu57boKSQ5CF+2ck0Ziybz2lHFbcl9RGhd0BAaWpjun89+wv4pSizf6yr8ODdnUmxPFH+o5i0TNfeKPvHkpVL7YwrLYvdmS6URYYKpxY3kPQbRxy92ZWl3po7rAAhAZaRHjnaRaBeFw0/zvD7pDhX4VNVBo6BufWMHxUoHzXUFOtSLGg==" Jan 16 19:14:39 volumio go-librespot[3405]: time="2025-01-16T19:14:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:39 volumio go-librespot[3405]: time="2025-01-16T19:14:39+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:39 volumio go-librespot[3405]: time="2025-01-16T19:14:39+01:00" level=debug msg="completed challenge" Jan 16 19:14:39 volumio go-librespot[3405]: time="2025-01-16T19:14:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:41 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:41 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 58. Jan 16 19:14:42 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:42 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:42 volumio go-librespot[3465]: Librespot-go daemon starting... Jan 16 19:14:42 volumio go-librespot[3465]: time="2025-01-16T19:14:42+01:00" level=info msg="generated new device id: 662fede7230e17e7a506be3e63b00b76511d41fe" Jan 16 19:14:42 volumio go-librespot[3465]: time="2025-01-16T19:14:42+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:42 volumio go-librespot[3465]: time="2025-01-16T19:14:42+01:00" level=debug msg="obtained new client token: AACR9+TfETgJifB6K4EwooO/PELhBKqDvflHDV8A5ps711Ypa+uABGJPzko1RFhrMRqRui767o17dzennzczWTA0vLAXnvZrB2sHBYVJcOccC9gLOCnLYOIs3sZmwXhRF8zgVbQuQg6jpGDnxw4rXHM1qTn9yynTYmSDHRX0TR8zudClBJSrgQ4FF6ASEKLUgPLAPBFQbkiHVa3lhMU0sV7CVpqyJ/P5GHYjjG2TUf/4wbVA/qoe2UIm6vaFKA==" Jan 16 19:14:43 volumio go-librespot[3465]: time="2025-01-16T19:14:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:43 volumio go-librespot[3465]: time="2025-01-16T19:14:43+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:43 volumio go-librespot[3465]: time="2025-01-16T19:14:43+01:00" level=debug msg="completed challenge" Jan 16 19:14:43 volumio go-librespot[3465]: time="2025-01-16T19:14:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:44 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:44 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:45 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:45 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:45 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:45 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:45 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:46 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. Jan 16 19:14:46 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:46 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:46 volumio go-librespot[3499]: Librespot-go daemon starting... Jan 16 19:14:46 volumio go-librespot[3499]: time="2025-01-16T19:14:46+01:00" level=info msg="generated new device id: 0ab5060ca90932deeae53382709bc58ba87f7983" Jan 16 19:14:46 volumio go-librespot[3499]: time="2025-01-16T19:14:46+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:46 volumio go-librespot[3499]: time="2025-01-16T19:14:46+01:00" level=debug msg="obtained new client token: AABYqDAZRRZRC/kx1d7RUK/5YA0TZuhwiJHLuCUIeJWqzWzlzR/ti08JZjLKUfe9HYLE62wm1vdFzlCS3nw7o2uWaO19RRiG/Mconuee8RHtu/kA6ZH1WMtjm+i04tZjs4bwCyvxcnQxjrZkfNGwqjJ1URSU99p0Uu1utmMr6P80lsXY2IcYOvq3qL1/J/n9t2T9zhLS3ILLccKAn7d2BidC6lZXwjjRaZrMR3LrDQ24C3kKtWNl/CFYrMEcPQ==" Jan 16 19:14:47 volumio go-librespot[3499]: time="2025-01-16T19:14:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:47 volumio go-librespot[3499]: time="2025-01-16T19:14:47+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:47 volumio volumio[815]: verbose: New Socket.io Connection to 192.168.1.16:3000 from 192.168.1.22 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Jan 16 19:14:47 volumio go-librespot[3499]: time="2025-01-16T19:14:47+01:00" level=debug msg="completed challenge" Jan 16 19:14:47 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:47 volumio go-librespot[3499]: time="2025-01-16T19:14:47+01:00" level=debug msg="new websocket client" Jan 16 19:14:47 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:14:47 volumio go-librespot[3499]: time="2025-01-16T19:14: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" Jan 16 19:14:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:47 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:14:49 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:50 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:14:50 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:14:50 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:14:50 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:50 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:14:50 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:14:50 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:50 volumio volumio[815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jan 16 19:14:50 volumio volumio[815]: (node:815) 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: 14) Jan 16 19:14:50 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:50 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 16 19:14:50 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:50 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:14:50 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:50 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. Jan 16 19:14:50 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:50 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:50 volumio go-librespot[3515]: Librespot-go daemon starting... Jan 16 19:14:50 volumio go-librespot[3515]: time="2025-01-16T19:14:50+01:00" level=info msg="generated new device id: 970168cfd6c98e20844fc7c83843b8471dab08c4" Jan 16 19:14:50 volumio go-librespot[3515]: time="2025-01-16T19:14:50+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:50 volumio go-librespot[3515]: time="2025-01-16T19:14:50+01:00" level=debug msg="obtained new client token: AADuEhqGg4XN5PRuUcOmOwuFYxPhaPiR+b+Xt/AMdALCqneQT7Eu7v3DuBoQIaiGtlNz3n82U2bulo9JOAvOvQn9DQZ+6Y96lM7WCinEV/2GxR7lYR+s+6rFoTzekQ5rJ5VImsM8BVIdUluRXos7+cR0ZEEZpVqP2QIWbD/Fpl5waX5rFvm8Qp8gyqVFx5JlevumSD3PGgwGwOnIm88YOLzogpjEKsSBf+iehR0mPNs0CRAQVPJ5n6HTHHXoSQ==" Jan 16 19:14:51 volumio go-librespot[3515]: time="2025-01-16T19:14:51+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:51 volumio go-librespot[3515]: time="2025-01-16T19:14:51+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:51 volumio go-librespot[3515]: time="2025-01-16T19:14:51+01:00" level=debug msg="completed challenge" Jan 16 19:14:51 volumio go-librespot[3515]: time="2025-01-16T19:14: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" Jan 16 19:14:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:53 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:53 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Jan 16 19:14:54 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:54 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:54 volumio go-librespot[3535]: Librespot-go daemon starting... Jan 16 19:14:54 volumio go-librespot[3535]: time="2025-01-16T19:14:54+01:00" level=info msg="generated new device id: 15536a9a904cb1650df0c5f9b5abacfc77c160ba" Jan 16 19:14:54 volumio go-librespot[3535]: time="2025-01-16T19:14:54+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:54 volumio go-librespot[3535]: time="2025-01-16T19:14:54+01:00" level=debug msg="obtained new client token: AAAYkNrkzoiDIaS4Tfo0n4Iu/ApFCvqGtXpuKQmysINsQ6fU9Jo0+y7+oRoR1Zodjtaqbf4P3UAGs09c70L1H602HNC0sN5wbUKBW/82kCh3eQmnjM4sryixj2TcdzPSZLa8Dcz2blBoFL8I8DkUKGzHYxpkN4oNCpDOHzgEglbzOoZpJLEl39tFw+QzdgoBvOpIV+XzJ1JPItg1EEmY5vEvA3HXqMdR8AHrABIaX2UtdFG9H58otDyQ4fyw+A==" Jan 16 19:14:55 volumio go-librespot[3535]: time="2025-01-16T19:14:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:14:55 volumio go-librespot[3535]: time="2025-01-16T19:14:55+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:55 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:55 volumio go-librespot[3535]: time="2025-01-16T19:14:55+01:00" level=debug msg="completed challenge" Jan 16 19:14:55 volumio go-librespot[3535]: time="2025-01-16T19:14:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:56 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:56 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:14:57 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:14:58 volumio kernel: usb 3-1: USB disconnect, device number 2 Jan 16 19:14:58 volumio volumio[815]: info: Jan 16 19:14:58 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:14:58 volumio volumio[815]: info: Jan 16 19:14:58 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:14:58 volumio volumio[815]: info: Jan 16 19:14:58 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand status took 5 milliseconds Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand status took 5 milliseconds Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand status took 4 milliseconds Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand clearerror took 5 milliseconds Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand playlistinfo took 2 milliseconds Jan 16 19:14:58 volumio volumio[815]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 16 19:14:58 volumio volumio[815]: verbose: ControllerMpd::parseTrackInfo Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:14:58 volumio volumio[815]: verbose: In UPNP mode Jan 16 19:14:58 volumio volumio[815]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":59654,"duration":154,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1331 Kbps","isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:14:58 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState stateService pause Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus play Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:14:58 volumio volumio[815]: verbose: In UPNP mode Jan 16 19:14:58 volumio volumio[815]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":59654,"duration":154,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1331 Kbps","isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:14:58 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState stateService pause Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus play Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:14:58 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:14:58 volumio volumio[815]: verbose: In UPNP mode Jan 16 19:14:58 volumio volumio[815]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":59654,"duration":154,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1331 Kbps","isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:14:58 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState stateService pause Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus play Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:14:58 volumio volumio[815]: info: ------------------------------ 18ms Jan 16 19:14:58 volumio volumio[815]: info: ------------------------------ 18ms Jan 16 19:14:58 volumio volumio[815]: info: ------------------------------ 18ms Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:14:58 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:14:58 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:14:58 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:14:58 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:14:58 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:58 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:58 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jan 16 19:14:58 volumio thd[664]: Error reading device '/dev/input/event3' Jan 16 19:14:58 volumio volumio[815]: info: Jan 16 19:14:58 volumio volumio[815]: ---------------------------- USB Audio Device Detached Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 16 19:14:58 volumio volumio[815]: aplay: device_list:272: no soundcards found... Jan 16 19:14:58 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Jan 16 19:14:58 volumio volumio[815]: info: No valid Plugin REST Endpoint Jan 16 19:14:58 volumio systemd[1]: Stopped target Sound Card. Jan 16 19:14:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:14:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. Jan 16 19:14:58 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:14:58 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:14:58 volumio go-librespot[3577]: Librespot-go daemon starting... Jan 16 19:14:58 volumio go-librespot[3577]: time="2025-01-16T19:14:58+01:00" level=info msg="generated new device id: 4b83eba9d35de7100b76a64ca17adf034a89fc36" Jan 16 19:14:58 volumio go-librespot[3577]: time="2025-01-16T19:14:58+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:14:58 volumio go-librespot[3577]: time="2025-01-16T19:14:58+01:00" level=debug msg="obtained new client token: AAC2hY4jFRhyvGIUwvdOLXvMxT9osnMfEVACWnEe5+Fcyri9HXGtR3JYg8kaVyoway5O4r6DRme72IPQLPa/qeTf0S9ygviVXSdAaVhBFP6JwiOqgY6RhXiygtnxN/KESjaOCYNs1CQ0h+uKedypn7seCAG9Gof455K1IZsZe40JmkProLiQ4C9h3cOAw3qBlAqrgdYV9YcGAEwqORu1YHrOYd/sPGayjioVy1uSmTxByt/TX+5osm5pG/TDZw==" Jan 16 19:14:59 volumio go-librespot[3577]: time="2025-01-16T19:14:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 16 19:14:59 volumio go-librespot[3577]: time="2025-01-16T19:14:59+01:00" level=debug msg="completed keyexchange" Jan 16 19:14:59 volumio go-librespot[3577]: time="2025-01-16T19:14:59+01:00" level=debug msg="completed challenge" Jan 16 19:14:59 volumio go-librespot[3577]: time="2025-01-16T19:14:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:14:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:14:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:14:59 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:14:59 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:00 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:15:00 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:15:00 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:15:00 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:00 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:15:02 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:02 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. Jan 16 19:15:02 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:02 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:02 volumio go-librespot[3585]: Librespot-go daemon starting... Jan 16 19:15:02 volumio go-librespot[3585]: time="2025-01-16T19:15:02+01:00" level=info msg="generated new device id: c430305ab064602176968e948740ff107c351095" Jan 16 19:15:02 volumio go-librespot[3585]: time="2025-01-16T19:15:02+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:02 volumio go-librespot[3585]: time="2025-01-16T19:15:02+01:00" level=debug msg="obtained new client token: AAByf4gSONInu2rwNQCw+UT1hAo60IdSN33JBfksgpUzQYxqJppr4VMmiQUUQTYZ/tzVwlVQicrSm8hLX9LRzGJnPHfep5EFGgB7lDqE9PNXK24dFWRW97YHrX9m0BSUkxhUN4T+J3IhS2xvlNga55A9yveMumnSi1dfbMVjfu3wjJcIV1+CdNMW8YokeboPKJX1HjfZupIjEd7f4UaGaGz+l8BM6WwWQ/UaTy4q7a9gRa5yrVXs7Je7g/zmfw==" Jan 16 19:15:03 volumio go-librespot[3585]: time="2025-01-16T19:15:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:03 volumio go-librespot[3585]: time="2025-01-16T19:15:03+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:03 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:03 volumio go-librespot[3585]: time="2025-01-16T19:15:03+01:00" level=debug msg="completed challenge" Jan 16 19:15:03 volumio go-librespot[3585]: time="2025-01-16T19:15:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:03 volumio kernel: usb 3-1: new full-speed USB device number 3 using xhci_hcd Jan 16 19:15:04 volumio kernel: usb 3-1: device descriptor read/64, error -71 Jan 16 19:15:04 volumio kernel: usb 3-1: device descriptor read/64, error -71 Jan 16 19:15:04 volumio kernel: usb 3-1: new full-speed USB device number 4 using xhci_hcd Jan 16 19:15:04 volumio kernel: usb 3-1: device descriptor read/64, error -71 Jan 16 19:15:04 volumio kernel: usb 3-1: device descriptor read/64, error -71 Jan 16 19:15:05 volumio kernel: usb usb3-port1: attempt power cycle Jan 16 19:15:05 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:05 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:05 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:05 volumio kernel: usb 3-1: new high-speed USB device number 5 using xhci_hcd Jan 16 19:15:05 volumio kernel: usb 3-1: New USB device found, idVendor=28d4, idProduct=0008, bcdDevice= 6.f2 Jan 16 19:15:05 volumio kernel: usb 3-1: New USB device strings: Mfr=1, Product=3, SerialNumber=0 Jan 16 19:15:05 volumio kernel: usb 3-1: Product: Expert Pro USB Audio 2.0 Jan 16 19:15:05 volumio kernel: usb 3-1: Manufacturer: DEVIALET Jan 16 19:15:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. Jan 16 19:15:06 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:06 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:06 volumio go-librespot[3614]: Librespot-go daemon starting... Jan 16 19:15:06 volumio go-librespot[3614]: time="2025-01-16T19:15:06+01:00" level=info msg="generated new device id: 07e208d7198cf2055f52d9ca61aefbc9fec8c957" Jan 16 19:15:06 volumio go-librespot[3614]: time="2025-01-16T19:15:06+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:06 volumio go-librespot[3614]: time="2025-01-16T19:15:06+01:00" level=debug msg="obtained new client token: AAAHFSp8HduM5r9t3+o9mvgd0qTriQ+U7KsFAxSjaejm8pAaz7sp79YZbf2rmpd/ie4hMarx/RqyJgkgnbYW6YeJA54pXOjvu6jNdXyr09FyX5JGANnLznsfDT3Am9nU2EHWMhkJ6CVvFfUmjE6QtgEDJR8H157INlKZwQ73ZO9XizKXEPT0BjKVxONBNTztWe+P88wgcFcLH+b4t0rDfCY9pKHXeC41/TI4gh6EIL1cnbhcEJRqBZzWplPxqQ==" Jan 16 19:15:07 volumio go-librespot[3614]: time="2025-01-16T19:15:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:07 volumio go-librespot[3614]: time="2025-01-16T19:15:07+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:07 volumio kernel: input: DEVIALET Expert Pro USB Audio 2.0 as /devices/pci0000:00/0000:00:1c.0/0000:02:00.0/usb3/3-1/3-1:1.4/0003:28D4:0008.0003/input/input6 Jan 16 19:15:07 volumio kernel: hid-generic 0003:28D4:0008.0003: input,hidraw0: USB HID v1.10 Device [DEVIALET Expert Pro USB Audio 2.0] on usb-0000:02:00.0-1/input4 Jan 16 19:15:07 volumio systemd[1]: Reached target Sound Card. Jan 16 19:15:07 volumio volumio[815]: info: No valid Plugin REST Endpoint Jan 16 19:15:07 volumio volumio[815]: info: Jan 16 19:15:07 volumio volumio[815]: ---------------------------- USB Audio Device Attached Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::Close All Modals sent Jan 16 19:15:07 volumio volumio[815]: info: Preparing to save Alsa Options, stopping services first Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::volumioPause Jan 16 19:15:07 volumio volumio[815]: info: CoreStateMachine::pause Jan 16 19:15:07 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:15:07 volumio volumio[815]: info: CoreStateMachine::servicePause Jan 16 19:15:07 volumio volumio[815]: info: CorePlayQueue::getTrack 0 Jan 16 19:15:07 volumio volumio[815]: info: Error: no service or no trackblock to pause Jan 16 19:15:07 volumio volumio[815]: info: Saving Audio Output to: {"disallowPush":true,"output_device":{"value":"5","label":"Expert Pro USB Audio 2.0","alsacard":"E20"},"i2s":false} Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 16 19:15:07 volumio volumio[815]: info: Setting mixer Expert Pro USB Audio 2.0 for card Expert Pro USB Audio 2.0 Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::volumioUpdateVolumeSettings Jan 16 19:15:07 volumio volumio[815]: info: Updating Volume Controller Parameters: Device: 5 Name: Expert Pro USB Audio 2.0 Mixer: Expert Pro USB Audio 2.0 Max Vol: 80 Vol Curve; logarithmic Vol Steps: 1 Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Jan 16 19:15:07 volumio volumio[815]: info: Disabling external Volume Control Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 16 19:15:07 volumio volumio[815]: info: Preparing to generate the ALSA configuration file Jan 16 19:15:07 volumio volumio[815]: info: Asound.conf file unchanged, so no further update is needed Jan 16 19:15:07 volumio volumio[815]: info: Output device has changed, restarting MPD Jan 16 19:15:07 volumio sudo[3648]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 16 19:15:07 volumio sudo[3648]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:15:07 volumio sudo[3648]: pam_unix(sudo:session): session closed for user root Jan 16 19:15:07 volumio volumio[815]: info: Output device has changed, restarting Shairport Sync Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 16 19:15:07 volumio sudo[3651]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 16 19:15:07 volumio sudo[3651]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:15:07 volumio systemd-udevd[3625]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Jan 16 19:15:07 volumio systemd[1]: Stopping Music Player Daemon... Jan 16 19:15:07 volumio volumio[815]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 16 19:15:07 volumio volumio[815]: info: MPD Permissions set Jan 16 19:15:07 volumio volumio[815]: info: VolumeController:: Volume=73 Mute =false Jan 16 19:15:07 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:07 volumio systemd[1]: mpd.service: Succeeded. Jan 16 19:15:07 volumio systemd[1]: Stopped Music Player Daemon. Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 16 19:15:07 volumio systemd[1]: Starting Music Player Daemon... Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:07 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:07 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:07 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:07 volumio volumio[815]: SPOTIFY: SPOTIFY VOLUME 75 Jan 16 19:15:07 volumio volumio[815]: SPOTIFY: VOLUMIO VOLUME 73 Jan 16 19:15:07 volumio volumio[815]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 16 19:15:07 volumio volumio[815]: info: Setting Spotify Volume from Volumio: 73 Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 16 19:15:07 volumio volumio[815]: info: Starting Shairport Sync Jan 16 19:15:07 volumio sudo[3656]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 16 19:15:07 volumio sudo[3656]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:15:07 volumio sudo[3656]: pam_unix(sudo:session): session closed for user root Jan 16 19:15:07 volumio sudo[3670]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 16 19:15:07 volumio sudo[3670]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:15:07 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jan 16 19:15:07 volumio systemd[1]: shairport-sync.service: Succeeded. Jan 16 19:15:07 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jan 16 19:15:07 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 16 19:15:07 volumio sudo[3670]: pam_unix(sudo:session): session closed for user root Jan 16 19:15:07 volumio volumio[815]: info: Shairport-Sync Started Jan 16 19:15:07 volumio mpd[3669]: Jan 16 19:15 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 16 19:15:07 volumio systemd[1]: Started Music Player Daemon. Jan 16 19:15:07 volumio sudo[3651]: pam_unix(sudo:session): session closed for user root Jan 16 19:15:07 volumio volumio[815]: error: updateQueue error: null Jan 16 19:15:07 volumio go-librespot[3614]: time="2025-01-16T19:15:07+01:00" level=debug msg="completed challenge" Jan 16 19:15:07 volumio go-librespot[3614]: time="2025-01-16T19:15:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:07 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: raat , restartRaat Jan 16 19:15:08 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:08 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:08 volumio volumio[815]: SPOTIFY: SETTING SPOTIFY VOLUME 73 Jan 16 19:15:08 volumio volumio[815]: info: Sending Spotify command with payload to local API: /player/volume Jan 16 19:15:08 volumio volumio[815]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:09 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. Jan 16 19:15:10 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:10 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:10 volumio go-librespot[3677]: Librespot-go daemon starting... Jan 16 19:15:10 volumio go-librespot[3677]: time="2025-01-16T19:15:10+01:00" level=info msg="generated new device id: 942bcbe012348548789cb18e767746dcd423319c" Jan 16 19:15:10 volumio go-librespot[3677]: time="2025-01-16T19:15:10+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:10 volumio go-librespot[3677]: time="2025-01-16T19:15:10+01:00" level=debug msg="obtained new client token: AAAENGh9+7cuCl6b0Ik/26So2Q5Wpx/OQ0IfVW/LkdQsHXw4aVy9wtzHftGzFqtdjSSH2DyejDMnhVHZ9B2cBRN3SaHdCIX23omgK43xfoFt+e6AAsuxkxabXRAHaA4bnIY+M8NQLpL1EWXOH1UTf/RV5KViMtZ7DO8d2ziz6uG1KWj17dzG8QK/r1uH79K3nWlZzhHiaenUzNPWCk5sE5LCuGrpQiY52BMTeUDFxg5D7fMiZR+zNZwqw2399g==" Jan 16 19:15:11 volumio go-librespot[3677]: time="2025-01-16T19:15:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::getcurrentVolume Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioRetrievevolume Jan 16 19:15:11 volumio volumio[815]: info: VolumeController:: Volume=73 Mute =false Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::updateTrackBlock Jan 16 19:15:11 volumio volumio[815]: info: CorePlayQueue::getTrackBlock Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioRetrievevolume Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:11 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:11 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:11 volumio volumio[815]: info: VolumeController:: Volume=73 Mute =false Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:11 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:11 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:11 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:11 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:11 volumio go-librespot[3677]: time="2025-01-16T19:15:11+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:11 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:11 volumio go-librespot[3677]: time="2025-01-16T19:15:11+01:00" level=debug msg="new websocket client" Jan 16 19:15:11 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:15:11 volumio go-librespot[3677]: time="2025-01-16T19:15:11+01:00" level=debug msg="completed challenge" Jan 16 19:15:12 volumio go-librespot[3677]: time="2025-01-16T19:15:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:12 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:15:13 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:14 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:15:14 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:14 volumio volumio[815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jan 16 19:15:14 volumio volumio[815]: (node:815) 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: 15) Jan 16 19:15:14 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 16 19:15:14 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:14 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:15 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:15 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Jan 16 19:15:15 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:15 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:15 volumio go-librespot[3692]: Librespot-go daemon starting... Jan 16 19:15:15 volumio go-librespot[3692]: time="2025-01-16T19:15:15+01:00" level=info msg="generated new device id: 72f79df9ec235d1419a335fdf148047ed64045f9" Jan 16 19:15:15 volumio go-librespot[3692]: time="2025-01-16T19:15:15+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:15 volumio go-librespot[3692]: time="2025-01-16T19:15:15+01:00" level=debug msg="obtained new client token: AABu7Fxpl6bvge6xVAC8QSL5CGnlltXWxiTQ2Jswx4baZqtruGGYMV10Crh4vS2l3Hlu6DIqbCU8NJqusuz9XWY57QHltzH54y2lDFOqMh+6Sdfl5UuhmeZCVWt0lfMnFhdrOFOc36pSjc71eSnjvizb/31aRFfJFYEEc7QYeAZaULnZ6AU5mPxPyIPDsjawQgLbgIFo/B4Ew9x1jVn/4bREFT7TG6neDBCwNYVygV8xQ+TRf0ijsalfGHQ5Qg==" Jan 16 19:15:15 volumio go-librespot[3692]: time="2025-01-16T19:15:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:15 volumio go-librespot[3692]: time="2025-01-16T19:15:15+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:16 volumio go-librespot[3692]: time="2025-01-16T19:15:16+01:00" level=debug msg="completed challenge" Jan 16 19:15:16 volumio go-librespot[3692]: time="2025-01-16T19:15:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:17 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:18 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:18 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:18 volumio volumio[815]: error: Upnp client error: Error: This socket has been ended by the other party Jan 16 19:15:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Jan 16 19:15:19 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:19 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:19 volumio go-librespot[3714]: Librespot-go daemon starting... Jan 16 19:15:19 volumio go-librespot[3714]: time="2025-01-16T19:15:19+01:00" level=info msg="generated new device id: f76429bc5b4c4ec2375a5204706094381cc7dfb3" Jan 16 19:15:19 volumio go-librespot[3714]: time="2025-01-16T19:15:19+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:19 volumio go-librespot[3714]: time="2025-01-16T19:15:19+01:00" level=debug msg="obtained new client token: AAC6pSRlIrJrL9NgRzhRpHITRgo4SpK2UFf2ZFqAVwu/6YHRtvC0oOLn43VRH3YQ0Q+zSx5pcvxsCyqGjztEXTj0RWojrdLJL6rRt8nVIZPdAuSMfo0XPLiHVwCqR04zVNohK6TJ+CCfim6buev+5IZ5mIKzQY9WGMwPWzjlrfcvGh6m5yqsMCXfax//lyZenTEgbFfmGpZqiVE9DW5wOQWyu/h5sl6cw6soFSOQZm186RyR8bmYBZppdqHdsw==" Jan 16 19:15:19 volumio go-librespot[3714]: time="2025-01-16T19:15:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:19 volumio go-librespot[3714]: time="2025-01-16T19:15:19+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:15:20 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:15:20 volumio go-librespot[3714]: time="2025-01-16T19:15:20+01:00" level=debug msg="completed challenge" Jan 16 19:15:20 volumio go-librespot[3714]: time="2025-01-16T19:15: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" Jan 16 19:15:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:20 volumio volumio[815]: info: Clearing queue after UPNP request Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 16 19:15:20 volumio volumio[815]: info: Discovery: Getting this device information Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::ClearQueue Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::stop Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::updateTrackBlock Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::getTrackBlock Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::getTrack 0 Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::serviceStop Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::getTrack 0 Jan 16 19:15:20 volumio volumio[815]: info: ControllerMpd::stop Jan 16 19:15:20 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand stop Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::clearPlayQueue Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::saveQueue Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioPushQueue Jan 16 19:15:20 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:20 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:20 volumio volumio[815]: info: Jan 16 19:15:20 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:20 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:20 volumio volumio[815]: info: sendMpdCommand stop took 5 milliseconds Jan 16 19:15:20 volumio volumio[815]: error: updateQueue error: null Jan 16 19:15:20 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:20 volumio volumio[815]: info: Starting UPNP Playback Jan 16 19:15:20 volumio volumio[815]: info: Preparing playback through UPNP Jan 16 19:15:20 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:20 volumio volumio[815]: info: CorePlayQueue::getTrack 0 Jan 16 19:15:20 volumio volumio[815]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:21 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:21 volumio volumio[815]: info: Starting UPNP Playback Jan 16 19:15:21 volumio volumio[815]: info: Preparing playback through UPNP Jan 16 19:15:21 volumio volumio[815]: info: Consume mode Jan 16 19:15:21 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:21 volumio volumio[815]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 1ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: Jan 16 19:15:21 volumio volumio[815]: ---------------------------- MPD announces system playlist update Jan 16 19:15:21 volumio volumio[815]: info: Ignoring MPD Status Update Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: ------------------------------ 0ms Jan 16 19:15:21 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:22 volumio volumio[815]: info: Jan 16 19:15:22 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:15:22 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:15:22 volumio volumio[815]: info: Jan 16 19:15:22 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:15:22 volumio volumio[815]: info: sendMpdCommand status took 431 milliseconds Jan 16 19:15:22 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:15:22 volumio volumio[815]: info: sendMpdCommand status took 0 milliseconds Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:15:22 volumio volumio[815]: info: sendMpdCommand playlistinfo took 0 milliseconds Jan 16 19:15:22 volumio volumio[815]: info: sendMpdCommand playlistinfo took 0 milliseconds Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::parseTrackInfo Jan 16 19:15:22 volumio volumio[815]: verbose: ControllerMpd::parseTrackInfo Jan 16 19:15:22 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:15:22 volumio volumio[815]: verbose: In UPNP mode Jan 16 19:15:22 volumio volumio[815]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":154,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1347 Kbps","isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:15:22 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::syncState stateService play Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus stop Jan 16 19:15:22 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:15:22 volumio volumio[815]: verbose: In UPNP mode Jan 16 19:15:22 volumio volumio[815]: verbose: STATE SERVICE {"status":"play","position":0,"seek":983,"duration":154,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1340 Kbps","isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:15:22 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::syncState stateService play Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus play Jan 16 19:15:22 volumio volumio[815]: info: Received an update from plugin. extracting info from payload Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:22 volumio volumio[815]: info: ------------------------------ 434ms Jan 16 19:15:22 volumio volumio[815]: info: ------------------------------ 6ms Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:22 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:22 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:22 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:22 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:22 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:22 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. Jan 16 19:15:23 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:23 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:23 volumio go-librespot[3734]: Librespot-go daemon starting... Jan 16 19:15:23 volumio go-librespot[3734]: time="2025-01-16T19:15:23+01:00" level=info msg="generated new device id: 5c85d1ce09b739cd39852a134c800d9cd3c7a67c" Jan 16 19:15:23 volumio go-librespot[3734]: time="2025-01-16T19:15:23+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:23 volumio go-librespot[3734]: time="2025-01-16T19:15:23+01:00" level=debug msg="obtained new client token: AAD8C2/U3XSEyQ2xapcX9rgb9ahAN6nhmApi16UmQo80/Sp1tNPUpwIXUoyZyGMyqpkYRskLVbALTyFYCEyPRXU4JcLt7MF8+uDwAwIhQll+sMxK2W8Pui5qwFd3Zjvbcbq1tCA5FrMi60EV8p7CV8Qq9pooA9t7cckO0riWc8tVUMnOlVD1XXs3UVbL/e8S3wcThES8UeL7pAT+zmS4E47gDkxhfHxwsxnzfhG3bFbJWPHD36SypD9Scdm+Fw==" Jan 16 19:15:23 volumio go-librespot[3734]: time="2025-01-16T19:15:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:23 volumio go-librespot[3734]: time="2025-01-16T19:15:23+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:24 volumio go-librespot[3734]: time="2025-01-16T19:15:24+01:00" level=debug msg="completed challenge" Jan 16 19:15:24 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:24 volumio go-librespot[3734]: time="2025-01-16T19:15:24+01:00" level=debug msg="new websocket client" Jan 16 19:15:24 volumio volumio[815]: info: Connection to go-librespot Websocket established Jan 16 19:15:24 volumio go-librespot[3734]: time="2025-01-16T19:15: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" Jan 16 19:15:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:24 volumio volumio[815]: info: Connection to go-librespot Websocket closed Jan 16 19:15:25 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:27 volumio volumio[815]: info: Getting Spotify volume Jan 16 19:15:27 volumio volumio[815]: (node:815) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:27 volumio volumio[815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jan 16 19:15:27 volumio volumio[815]: (node:815) 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: 16) Jan 16 19:15:27 volumio volumio[815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 16 19:15:27 volumio volumio[815]: info: CoreCommandRouter::volumioGetState Jan 16 19:15:27 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:27 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:27 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Jan 16 19:15:27 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:27 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:27 volumio go-librespot[3760]: Librespot-go daemon starting... Jan 16 19:15:27 volumio go-librespot[3760]: time="2025-01-16T19:15:27+01:00" level=info msg="generated new device id: ecc1032968ef18e3cc70374298d24c8b176a2058" Jan 16 19:15:27 volumio go-librespot[3760]: time="2025-01-16T19:15:27+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:27 volumio go-librespot[3760]: time="2025-01-16T19:15:27+01:00" level=debug msg="obtained new client token: AAASGkjSUcAhmfRewKGBtMhXisioLETTaeyP/lFV4OsP7JhO028An8/ikoziFKpHXJ7V7s7KITyQr56TS3r7asKMEXCzy58psxEAh5nSlMhBSljawZ4eFttg78Na9UbuBz0uzsidVlZ8bis96XgeCHc5C4Ef+usZG7hCNrgq40mPcWjnOhqrkF9ybu4gw+ALEzhS7aVzjl8P66+Mu54BVLhsUZqWhXaw6PSt3Wx9by5TVGNVaW0vHcdlcUCFSw==" Jan 16 19:15:27 volumio go-librespot[3760]: time="2025-01-16T19:15:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:27 volumio go-librespot[3760]: time="2025-01-16T19:15:27+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:28 volumio go-librespot[3760]: time="2025-01-16T19:15:28+01:00" level=debug msg="completed challenge" Jan 16 19:15:28 volumio go-librespot[3760]: time="2025-01-16T19:15: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" Jan 16 19:15:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:30 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:30 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:31 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Jan 16 19:15:31 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:31 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:31 volumio go-librespot[3768]: Librespot-go daemon starting... Jan 16 19:15:31 volumio go-librespot[3768]: time="2025-01-16T19:15:31+01:00" level=info msg="generated new device id: 29794d65f776308fac1f5816b3b9cc37e4888066" Jan 16 19:15:31 volumio go-librespot[3768]: time="2025-01-16T19:15:31+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:31 volumio go-librespot[3768]: time="2025-01-16T19:15:31+01:00" level=debug msg="obtained new client token: AADMgpXPG3foEgsoCDjxAZ7/bwoANytnrzPu8KNlUUNZ32p/tJPWK0SPiVu4UD0rvUIO+Oex1ATsozjT3AnWmUaZ54UQ4tx6TsLlOskds0SnUb88mjreXiBc0PHJ/vbOYyLBNqgc7IE3LYP1yire3LLYHFP26SlgZgXlwebtxdUaFpRvkmEw41+4sTpLNDhAZtIrG3hRKV2aOATyL7xpgAKIwxOd58D2r9zJKegdX+URa1E5WIPa51PT1GuBcQ==" Jan 16 19:15:31 volumio go-librespot[3768]: time="2025-01-16T19:15:31+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:31 volumio go-librespot[3768]: time="2025-01-16T19:15:31+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:32 volumio go-librespot[3768]: time="2025-01-16T19:15:32+01:00" level=debug msg="completed challenge" Jan 16 19:15:32 volumio go-librespot[3768]: time="2025-01-16T19:15:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:33 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:33 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:33 volumio volumio[815]: info: Jan 16 19:15:33 volumio volumio[815]: ---------------------------- MPD announces state update: player Jan 16 19:15:33 volumio volumio[815]: info: ControllerMpd::getState Jan 16 19:15:33 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand status Jan 16 19:15:33 volumio volumio[815]: info: sendMpdCommand status took 0 milliseconds Jan 16 19:15:33 volumio volumio[815]: verbose: ControllerMpd::parseState Jan 16 19:15:33 volumio volumio[815]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 16 19:15:33 volumio volumio[815]: info: sendMpdCommand playlistinfo took 0 milliseconds Jan 16 19:15:33 volumio volumio[815]: verbose: ControllerMpd::parseTrackInfo Jan 16 19:15:33 volumio volumio[815]: info: ControllerMpd::pushState Jan 16 19:15:33 volumio volumio[815]: info: CoreCommandRouter::servicePushState Jan 16 19:15:33 volumio volumio[815]: info: CoreStateMachine::pushState Jan 16 19:15:33 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:33 volumio volumio[815]: info: CorePlayQueue::getTrack 0 Jan 16 19:15:33 volumio volumio[815]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Enrich","artist":"Valter Nowak","album":"Dark Matter","uri":"https://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEic3MzZiZGMyN2QxZjk1OGEyM2E0NmZkMTQzY2EwYWNhMV82Mi5tcDQ/0.flac?token=1737054775~ZjlmZThhYTlhOGM2NjNhMTAwZTcxMjg3OGRlZDM3ZGFjYWVkNDljNQ==","trackType":"tidal"} Jan 16 19:15:33 volumio volumio[815]: verbose: CURRENT POSITION 0 Jan 16 19:15:33 volumio volumio[815]: info: CoreStateMachine::syncState stateService stop Jan 16 19:15:33 volumio volumio[815]: info: CoreStateMachine::syncState currentStatus play Jan 16 19:15:33 volumio volumio[815]: info: CoreCommandRouter::volumioPushState Jan 16 19:15:33 volumio volumio[815]: info: CoreStateMachine::stPlaybackTimer Jan 16 19:15:33 volumio volumio[815]: info: ------------------------------ 5ms Jan 16 19:15:33 volumio volumio[815]: info: CoreCommandRouter::volumioGetQueue Jan 16 19:15:33 volumio volumio[815]: info: CoreStateMachine::getQueue Jan 16 19:15:33 volumio volumio[815]: info: CorePlayQueue::getQueue Jan 16 19:15:33 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:33 volumio volumio[815]: SPOTIFY: RECEIVED VOLUMIO VOLUME 73 Jan 16 19:15:33 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Jan 16 19:15:35 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:35 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:35 volumio go-librespot[3779]: Librespot-go daemon starting... Jan 16 19:15:35 volumio go-librespot[3779]: time="2025-01-16T19:15:35+01:00" level=info msg="generated new device id: daeb7935563e628adec123ec10b06425e45db443" Jan 16 19:15:35 volumio go-librespot[3779]: time="2025-01-16T19:15:35+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:35 volumio go-librespot[3779]: time="2025-01-16T19:15:35+01:00" level=debug msg="obtained new client token: AACaP7whACG5kXYCwTCVQZIDWk2EOutp72tfie5gy5zR1vP+GkfyGo9+bmHh5JRscoEizrjYiyMRGcjgMMQGhMUc6HMT3mTYe+aU5gSFATGAiaT55vppZWJ/bldzLxBNgF9XOJpeeuYNGn+H9EXQoTPKhd3662agihTM5ljsc4y3oQVcyCmm72LNc1Sy55HRp+5RiBIag/JAkylB3PCMR1t6hqbAinDIr8DykmWD6i7PRG1LIkoGTB86fvESPA==" Jan 16 19:15:35 volumio go-librespot[3779]: time="2025-01-16T19:15:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 16 19:15:35 volumio go-librespot[3779]: time="2025-01-16T19:15:35+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:36 volumio go-librespot[3779]: time="2025-01-16T19:15:36+01:00" level=debug msg="completed challenge" Jan 16 19:15:36 volumio go-librespot[3779]: time="2025-01-16T19:15:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:36 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:36 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:36 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:39 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:39 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 16 19:15:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Jan 16 19:15:39 volumio systemd[1]: Stopped go-librespot Daemon. Jan 16 19:15:39 volumio systemd[1]: Started go-librespot Daemon. Jan 16 19:15:39 volumio go-librespot[3801]: Librespot-go daemon starting... Jan 16 19:15:39 volumio go-librespot[3801]: time="2025-01-16T19:15:39+01:00" level=info msg="generated new device id: 22c36a1f58fa2b34f7b42e97539f75eeb74c45e3" Jan 16 19:15:39 volumio go-librespot[3801]: time="2025-01-16T19:15:39+01:00" level=debug msg="stored credentials found for sloam8" Jan 16 19:15:39 volumio go-librespot[3801]: time="2025-01-16T19:15:39+01:00" level=debug msg="obtained new client token: AABz7sJtnSmHj23jVlmskF/YlgC4V9y/BEN/5cNWtsjrJDDSPE3g3+j770Wi3aEMUQ71b2SZuIjEM9XSEHIYSBU6aSXnC9/j0KE+zzaMm9j+nziHI9rlX9PXDqcGfmppSUTKgtQxxVIOMTprm3k8M5wQcYd5bnkHd87nd/qQPlgfyvPh0KAq0gERsx1fay7xuxbRDnS9X05aJMy0FxiCMIl+O2UTlsNCs3YTHIICEhRdhMinvq+6uYP9aT9yGg==" Jan 16 19:15:39 volumio go-librespot[3801]: time="2025-01-16T19:15:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 16 19:15:39 volumio go-librespot[3801]: time="2025-01-16T19:15:39+01:00" level=debug msg="completed keyexchange" Jan 16 19:15:40 volumio go-librespot[3801]: time="2025-01-16T19:15:40+01:00" level=debug msg="completed challenge" Jan 16 19:15:40 volumio go-librespot[3801]: time="2025-01-16T19:15:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 16 19:15:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 16 19:15:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 16 19:15:40 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 16 19:15:41 volumio volumio[815]: info: Disabling MyMusic plugin upnp Jan 16 19:15:41 volumio sudo[3810]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jan 16 19:15:41 volumio sudo[3810]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 16 19:15:41 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Jan 16 19:15:41 volumio volumio[815]: error: Upnp client error: Error: This socket has been ended by the other party Jan 16 19:15:42 volumio volumio[815]: info: Initializing connection to go-librespot Websocket Jan 16 19:15:42 volumio volumio[815]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 16 19:15:43 volumio volumio[815]: info: Enabling MyMusic plugin upnp Jan 16 19:15:43 volumio volumio[815]: info: Enabling plugin upnp Jan 16 19:15:43 volumio volumio[815]: info: Loading plugin "upnp"... Jan 16 19:15:43 volumio volumio[815]: info: [1737051343014] Starting Upmpd Daemon Jan 16 19:15:43 volumio volumio[815]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 16 19:15:43 volumio volumio[815]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 16 19:15:43 volumio volumio[815]: Error: listen EADDRINUSE: address already in use :::6599 Jan 16 19:15:43 volumio volumio[815]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Jan 16 19:15:43 volumio volumio[815]: at listenInCluster (net.js:1379:12) Jan 16 19:15:43 volumio volumio[815]: at Server.listen (net.js:1465:7) Jan 16 19:15:43 volumio volumio[815]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Jan 16 19:15:43 volumio volumio[815]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Jan 16 19:15:43 volumio volumio[815]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jan 16 19:15:43 volumio volumio[815]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jan 16 19:15:43 volumio volumio[815]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Jan 16 19:15:43 volumio volumio[815]: code: 'EADDRINUSE', Jan 16 19:15:43 volumio volumio[815]: errno: -98, Jan 16 19:15:43 volumio volumio[815]: syscall: 'listen', Jan 16 19:15:43 volumio volumio[815]: address: '::', Jan 16 19:15:43 volumio volumio[815]: port: 6599 Jan 16 19:15:43 volumio volumio[815]: } Jan 16 19:15:43 volumio volumio[815]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 16 19:15:43 volumio sudo[3865]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-16 19:14 Jan 16 19:15:43 volumio sudo[3865]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 07:25:16 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="66c567362bdbb3dc1644a18f7879afe7"