-- Logs begin at Sun 2024-09-01 10:44:09 +04, end at Sun 2024-09-01 13:07:52 +04. -- Sep 01 13:06:00 volumio-mbr go-librespot[27298]: time="2024-09-01T13:06:00+04:00" level=debug msg="completed challenge" Sep 01 13:06:00 volumio-mbr go-librespot[27298]: time="2024-09-01T13:06:00+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:00 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:00 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:00 volumio-mbr volumio[831]: info: Connection to go-librespot Websocket closed Sep 01 13:06:02 volumio-mbr volumio[831]: info: Getting Spotify volume Sep 01 13:06:02 volumio-mbr volumio[831]: (node:831) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:02 volumio-mbr volumio[831]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 01 13:06:02 volumio-mbr volumio[831]: (node:831) 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: 21466) Sep 01 13:06:02 volumio-mbr volumio[831]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Sep 01 13:06:02 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:02 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:02 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 01 13:06:03 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:03 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:03 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:03 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222075. Sep 01 13:06:03 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:03 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:03 volumio-mbr go-librespot[27306]: Librespot-go daemon starting... Sep 01 13:06:03 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:03+04:00" level=info msg="generated new device id: 326216570261e337466c4fe0532454557e7842fb" Sep 01 13:06:03 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:03+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:03 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:03+04:00" level=debug msg="obtained new client token: AAArsm0tdwsZHJYdpWHUMaDgsDOSERNThosUMpr3fxPa2m/2SAe6VTvhZYxbxNFgubkDFAAEDZ/a1T4AOYaPadU/xcXqcE3OE5eKTHG2Q8bzjIlH9s2M2hsv7KREvbPQA8MvBPk09LjF6zf4hJmXpREhbIsTgSYA91zgytjHLWY4hRbW8BFi7GQGDka8oX6rtccJ0gJZyDfYvIfu0rN/nUSwFwqofoc57eDNIsI8Rty7shAxqom37CPGQPJVmw==" Sep 01 13:06:03 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:03+04: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]" Sep 01 13:06:04 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:04+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:04 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:04+04:00" level=debug msg="completed challenge" Sep 01 13:06:04 volumio-mbr go-librespot[27306]: time="2024-09-01T13:06:04+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:04 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:04 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:06 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:06 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:07 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:07 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222076. Sep 01 13:06:07 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:07 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:07 volumio-mbr go-librespot[27314]: Librespot-go daemon starting... Sep 01 13:06:07 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:07+04:00" level=info msg="generated new device id: a01c8ee76564e54a170b02c48aa6ab9315f63a4f" Sep 01 13:06:07 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:07+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:08 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:08+04:00" level=debug msg="obtained new client token: AABdgvUZTAKN2l6jYInumfEN5rlYL7GOWrZVRZJ4DJQfPhifcQgZIagL6aC5F9EyU3RotjCohljqkOD8nfqWGZmK9v+vt0JSH6dQybWPKaPc4+4iU5Z6k++o8T/i2jC8H6m0tEJaD9LD9i9iZAvP+aErSrEpYb14GbUXk7lsPpnbb3pBzU9mxwtSJfsBV5DD5mxfXMA0Mawc4VIkxRWayyLJjmfnMY2inErweFjP5sZoXIgLvc5AIr1vfnM=" Sep 01 13:06:08 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:08+04: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]" Sep 01 13:06:08 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:08+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:09 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:09 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:09 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:09+04:00" level=debug msg="completed challenge" Sep 01 13:06:09 volumio-mbr go-librespot[27314]: time="2024-09-01T13:06:09+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:09 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:09 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:09 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:09 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:12 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:12 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:12 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:12 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222077. Sep 01 13:06:12 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:12 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:12 volumio-mbr go-librespot[27324]: Librespot-go daemon starting... Sep 01 13:06:12 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:12+04:00" level=info msg="generated new device id: fd27a98cb80f0120bbfd50ba9a1c1b59378efaa0" Sep 01 13:06:12 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:12+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:12 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:12+04:00" level=debug msg="obtained new client token: AABPLtWnUV+2XqxW74RSMrd/tSatxhcKR6/9665hOHgJtlBF2x2Fc59QJmZwB8vMGVanI/lsv2PDHzvvhQ18bfpIys+KBxsQZ9eSs+mEORi0RH1FlRs/VEDuIJzr+POGeG1xeimPU6eE6M2VGujcDVoxZRUPidH/rIjF2RFgirqBsV9JGh77BF0JtlhoUMd9sY7OEo8d9mpdO/V1nE2ajSLPR/Jgcc9XYSb0RlqvtAgxXQ8FTf6SR6aUFVGTAg==" Sep 01 13:06:12 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:12+04: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]" Sep 01 13:06:13 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:13+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:13 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:13+04:00" level=debug msg="completed challenge" Sep 01 13:06:13 volumio-mbr go-librespot[27324]: time="2024-09-01T13:06:13+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:13 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:13 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:14 volumio-mbr sudo[27334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 13:06:14 volumio-mbr sudo[27334]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:14 volumio-mbr sudo[27334]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:14 volumio-mbr sudo[27337]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 13:06:14 volumio-mbr sudo[27337]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:14 volumio-mbr sudo[27337]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:15 volumio-mbr volumio[831]: verbose: New Socket.io Connection to 192.168.10.44 from 192.168.10.149 UA: Mozilla/5.0 (Linux; Android 14; SM-F936B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/127.0.6533.103 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Sep 01 13:06:15 volumio-mbr sudo[27340]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 13:06:15 volumio-mbr sudo[27340]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:15 volumio-mbr sudo[27340]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:15 volumio-mbr sudo[27343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 13:06:15 volumio-mbr sudo[27343]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:15 volumio-mbr sudo[27343]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:15 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:15 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:15 volumio-mbr volumio[831]: verbose: New Socket.io Connection to 192.168.10.44 from 192.168.10.149 UA: Mozilla/5.0 (Linux; Android 14; SM-F936B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/127.0.6533.103 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:15 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetQueue Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreStateMachine::getQueue Sep 01 13:06:15 volumio-mbr volumio[831]: info: CorePlayQueue::getQueue Sep 01 13:06:15 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 13:06:15 volumio-mbr volumio[831]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Sep 01 13:06:15 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:15 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:15 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:15 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 01 13:06:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 01 13:06:16 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:16 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222078. Sep 01 13:06:16 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:16 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:16 volumio-mbr go-librespot[27345]: Librespot-go daemon starting... Sep 01 13:06:16 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:16+04:00" level=info msg="generated new device id: cecfebcea8466a0354ded75140d77b724d508725" Sep 01 13:06:16 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:16+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 01 13:06:17 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:17+04:00" level=debug msg="obtained new client token: AACefALc4jmgPQl81MeJOFATQLzx99VFCqt8bYFl6fhbm+OjLb+uK5ScB2uS9OnrwPgSwMkWdsxR9xNsPSbdYj5myDwjGf75wZ0oKBx3omvBfGfVEqE81I/4iPH+XRVa4ykqKKAAoFenZXEz6w0Jk8L718zY8EGlODt4EsyaLDQx3wohLhCWl8BA7Ls6AsaWIkBcEHsh5g+uiaHna7JDWD7pwPvxV5kg+0pOFssSOkvvJFyvyvxZFMo0ETE=" Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 13:06:17 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:17 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:17 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:17 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:17 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:17+04: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]" Sep 01 13:06:17 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:17+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:18 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:18+04:00" level=debug msg="completed challenge" Sep 01 13:06:18 volumio-mbr go-librespot[27345]: time="2024-09-01T13:06:18+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:18 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:18 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:18 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:18 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:18 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 13:06:18 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:18 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:18 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:18 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:18 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:18 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:18 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:19 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPlay Sep 01 13:06:19 volumio-mbr volumio[831]: info: CoreStateMachine::play index undefined Sep 01 13:06:19 volumio-mbr volumio[831]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 01 13:06:19 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:19 volumio-mbr volumio[831]: info: CoreStateMachine::startPlaybackTimer Sep 01 13:06:19 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:19 volumio-mbr volumio[831]: info: [1725181579043] ControllerSpotify::clearAddPlayTrack Sep 01 13:06:19 volumio-mbr volumio[831]: info: Sending Spotify command with payload to local API: /player/play Sep 01 13:06:19 volumio-mbr volumio[831]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:19 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:19 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:19 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:19 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:20 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume+ Sep 01 13:06:20 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:20 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:20 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:20 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:20 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:20 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:20 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:20 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:20 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Sep 01 13:06:20 volumio-mbr volumio[831]: SPOTIFY: SPOTIFY VOLUME 33 Sep 01 13:06:20 volumio-mbr volumio[831]: SPOTIFY: VOLUMIO VOLUME 34 Sep 01 13:06:20 volumio-mbr volumio[831]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 01 13:06:21 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:21 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:21 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:21 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222079. Sep 01 13:06:21 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:21 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:21 volumio-mbr go-librespot[27354]: Librespot-go daemon starting... Sep 01 13:06:21 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:21+04:00" level=info msg="generated new device id: d98e3b9f69526c51b84de4a61276634704f68f39" Sep 01 13:06:21 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:21+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:21 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:21+04:00" level=debug msg="obtained new client token: AACq1kPrUIHcWRAtYEL7fINm2HKDaFCzXJ19t1uoRgBfXWqYx6BdQRSyMTLByxpbQ603ZpqdUchJmAleeiUWRFf90KcL8F8PBWu23B8HwtgmKfzWjoxQWFsC33wuKW6/P0IPxMtkL/K2xkdyAXOS3B27R+mSNwbZZaSpyeR+gmNYGBHoGtJE0EGZfWhpn0mi3VznIIxdse7Tl7k/sGpdg8E4JwtZe8uNo4iRKzpVlBhPy7cKtcHUGbAICZogBw==" Sep 01 13:06:21 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:21+04: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]" Sep 01 13:06:21 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume+ Sep 01 13:06:21 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:21 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:21 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:21 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:21 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:21 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:21 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:21 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:21 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 01 13:06:21 volumio-mbr volumio[831]: SPOTIFY: SPOTIFY VOLUME 33 Sep 01 13:06:21 volumio-mbr volumio[831]: SPOTIFY: VOLUMIO VOLUME 35 Sep 01 13:06:21 volumio-mbr volumio[831]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 01 13:06:21 volumio-mbr volumio[831]: info: Setting Spotify Volume from Volumio: 35 Sep 01 13:06:22 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:22+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:22 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume+ Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: SPOTIFY VOLUME 35 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: VOLUMIO VOLUME 36 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 01 13:06:22 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:22+04:00" level=debug msg="completed challenge" Sep 01 13:06:22 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume+ Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: SPOTIFY VOLUME 35 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: VOLUMIO VOLUME 37 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 01 13:06:22 volumio-mbr volumio[831]: info: Setting Spotify Volume from Volumio: 37 Sep 01 13:06:22 volumio-mbr go-librespot[27354]: time="2024-09-01T13:06:22+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:22 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:22 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:22 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume+ Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:22 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:22 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: SPOTIFY VOLUME 37 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: VOLUMIO VOLUME 38 Sep 01 13:06:22 volumio-mbr volumio[831]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 01 13:06:24 volumio-mbr volumio[831]: SPOTIFY: SETTING SPOTIFY VOLUME 37 Sep 01 13:06:24 volumio-mbr volumio[831]: info: Sending Spotify command with payload to local API: /player/volume Sep 01 13:06:24 volumio-mbr volumio[831]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:24 volumio-mbr volumio[831]: info: VolumeController::SetAlsaVolume- Sep 01 13:06:24 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:24 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:24 volumio-mbr volumio[831]: info: CoreStateMachine::pushState Sep 01 13:06:24 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:24 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 13:06:24 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioPushState Sep 01 13:06:24 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output update for this device Sep 01 13:06:24 volumio-mbr volumio[831]: info: MRS: Pushing multiroomSync output Sep 01 13:06:24 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Sep 01 13:06:24 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:24 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:25 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 01 13:06:25 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:25 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222080. Sep 01 13:06:25 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:25 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:25 volumio-mbr go-librespot[27406]: Librespot-go daemon starting... Sep 01 13:06:25 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:25+04:00" level=info msg="generated new device id: ae3ea51212deff678305271147ad6cdf030103af" Sep 01 13:06:25 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:25+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:26 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:26+04:00" level=debug msg="obtained new client token: AADLUkP3nKFCt+pSi8f5rSt4AQn7JTzvv6b0eo1S1hosTBqL9mgFLfH4voWAwnRAa0fgkrpwsF2lIzQNYCxP9KDSJWvGRFkJE5XKyEovsvyOVupxdB7kZf7/jvmDFxdgx0XVoBnljJK056m/7y2UKsLAG6RSa6oLTxsHS1dMrFfwiI1dvWVAclwFbXpG9JlYu0rGdWkMcYKYhq0ZwOVPNkMtVrsVUcO5EVswpCGP6vBoIx+X+oB2rPVT+yo=" Sep 01 13:06:26 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:26+04: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]" Sep 01 13:06:26 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:26+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:27 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:27+04:00" level=debug msg="completed challenge" Sep 01 13:06:27 volumio-mbr go-librespot[27406]: time="2024-09-01T13:06:27+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:27 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:27 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:27 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:27 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:27 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:27 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:27 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:29 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:29 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:30 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:30 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:30 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222081. Sep 01 13:06:30 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:30 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:30 volumio-mbr go-librespot[27415]: Librespot-go daemon starting... Sep 01 13:06:30 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:30+04:00" level=info msg="generated new device id: 5edd2a1ee832ea9a65114386f0367473abde917f" Sep 01 13:06:30 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:30+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:30 volumio-mbr sudo[27424]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 13:06:30 volumio-mbr sudo[27424]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:30 volumio-mbr sudo[27424]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:30 volumio-mbr sudo[27429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 13:06:30 volumio-mbr sudo[27429]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:30 volumio-mbr sudo[27429]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:30 volumio-mbr volumio[831]: verbose: New Socket.io Connection to 192.168.10.44 from 192.168.10.149 UA: Mozilla/5.0 (Linux; Android 14; SM-F936B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/127.0.6533.103 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Sep 01 13:06:30 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:30 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetQueue Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreStateMachine::getQueue Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getQueue Sep 01 13:06:30 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 13:06:30 volumio-mbr volumio[831]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Sep 01 13:06:30 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:30 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:30 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:30 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:30+04:00" level=debug msg="obtained new client token: AAD2w5VT7BDc1f2zYlp5+EPRpgZFCpaYShRMvJXSjKoMpI93HS2ppBdCSBtCehvutTVDbd/ZPHe8SHG0i/3FGEqL5otJSWFsq8dvnbtEbcLHN5aw8AIj+EUTbTSHhP8LLfBf+m8G7szjqqt5Hte1vBin8D1UEF082GiFtnPCH5DovHq6Uh3unYGU1liF1QlHWUtKpIl6qn4whK3xGzqPw80zaHVawH7HUB9Sc/gXC6KJwP5DURq762+HBvZb6Q==" Sep 01 13:06:30 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:30+04: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]" Sep 01 13:06:30 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 01 13:06:31 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:31+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:31 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:31+04:00" level=debug msg="completed challenge" Sep 01 13:06:31 volumio-mbr go-librespot[27415]: time="2024-09-01T13:06:31+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:31 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:31 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:32 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 13:06:32 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:32 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:32 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:32 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:32 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:32 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:32 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:33 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:33 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 01 13:06:33 volumio-mbr volumio[831]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Sep 01 13:06:33 volumio-mbr volumio[831]: info: Received Get System Version Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 13:06:33 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:33 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:33 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:33 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:34 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:34 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222082. Sep 01 13:06:34 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:34 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:34 volumio-mbr go-librespot[27431]: Librespot-go daemon starting... Sep 01 13:06:34 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:34+04:00" level=info msg="generated new device id: 28463ef719194955178036d1215a8284030a8dfe" Sep 01 13:06:34 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:34+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:35 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:35+04:00" level=debug msg="obtained new client token: AACLy/njZWQNZLj644zUjL8VICbY49O7LXkO98SI5p2iFzeg9tgrbb5IIycuBQuRFWFm2XOCuSQ7DFzeq1MHnQkTMiHFb46duYMzNakEs5aMMa3o/jrywmfftB141hUzZ2e2O+GSDH04ZzJcwkOt6M4x6GW2GycODTtRJ3dvmyE4qPYwg+spc7z9K0oeobzrLmLnLOijaox6PqQV/mQdKwQ6ViBbnfAXHTvwyWfZd+H9gOMHhAPs8Jl++Kk=" Sep 01 13:06:35 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:35+04: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]" Sep 01 13:06:35 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:35+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:36 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:36+04:00" level=debug msg="completed challenge" Sep 01 13:06:36 volumio-mbr go-librespot[27431]: time="2024-09-01T13:06:36+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:36 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:36 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:36 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:36 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:38 volumio-mbr sudo[27440]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 13:06:38 volumio-mbr sudo[27440]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:38 volumio-mbr sudo[27440]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:38 volumio-mbr sudo[27443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 13:06:38 volumio-mbr sudo[27443]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:38 volumio-mbr sudo[27443]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:38 volumio-mbr volumio[831]: verbose: New Socket.io Connection to 192.168.10.44 from 192.168.10.149 UA: Mozilla/5.0 (Linux; Android 14; SM-F936B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/127.0.6533.103 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Sep 01 13:06:38 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:38 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetQueue Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreStateMachine::getQueue Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getQueue Sep 01 13:06:38 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 13:06:38 volumio-mbr volumio[831]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Sep 01 13:06:38 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:38 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: Received Get System Info Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:38 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:38 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:38 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 01 13:06:39 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:39 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:39 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:39 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:39 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:39 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:39 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:39 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222083. Sep 01 13:06:39 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:39 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:39 volumio-mbr go-librespot[27446]: Librespot-go daemon starting... Sep 01 13:06:39 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:39+04:00" level=info msg="generated new device id: 973254a334584e5ffb91f6fdaaddb037f2a2be2c" Sep 01 13:06:39 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:39+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:39 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:39+04:00" level=debug msg="obtained new client token: AADB2IJkjqTdRZ0giNHSl+InDR5oqFFx0X+bIwQLChvsReKni8wO1ohxWArVFBF82AVD+wYz1G1Ci8O+v8AwFwcGkPHf73q2azaFMHWbOlwUyKdynnmAvdMALRrlafh2V7dpYsIFud9LBz3t2ZdD5SNiMiyCKDWN1faLmCAU7GAQftIawSD6WzGPMLpiXTxPb0ATcyuRr0QhzfD1TS9oUfDhIYQndcILZkwkvBZLSva8NDVDvSfhemtOmPi1EQ==" Sep 01 13:06:39 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:39+04: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]" Sep 01 13:06:40 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:40+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:40 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:40+04:00" level=debug msg="completed challenge" Sep 01 13:06:40 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 01 13:06:40 volumio-mbr go-librespot[27446]: time="2024-09-01T13:06:40+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:40 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:40 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:42 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:42 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:42 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:06:42 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 01 13:06:42 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Sep 01 13:06:42 volumio-mbr sudo[27457]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Sep 01 13:06:42 volumio-mbr sudo[27457]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27457]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:42 volumio-mbr sudo[27464]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 01 13:06:42 volumio-mbr sudo[27464]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27464]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:42 volumio-mbr sudo[27472]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 01 13:06:42 volumio-mbr sudo[27472]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27472]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:42 volumio-mbr sudo[27477]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 01 13:06:42 volumio-mbr sudo[27477]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27477]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:42 volumio-mbr sudo[27483]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 13:06:42 volumio-mbr sudo[27483]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27483]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:42 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Sep 01 13:06:42 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Sep 01 13:06:42 volumio-mbr sudo[27486]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 13:06:42 volumio-mbr sudo[27486]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 13:06:42 volumio-mbr sudo[27486]: pam_unix(sudo:session): session closed for user root Sep 01 13:06:43 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:43 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222084. Sep 01 13:06:43 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:43 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:43 volumio-mbr go-librespot[27488]: Librespot-go daemon starting... Sep 01 13:06:43 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:43+04:00" level=info msg="generated new device id: 10bf3193ce97b54c4c7c48cc93fee6ded437a56b" Sep 01 13:06:43 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:43+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:44 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:44+04:00" level=debug msg="obtained new client token: AAB5uYpbSIiNYo1t9r2m0uifG+tRUT1LXlynsOArpuXCZ88f/1QNfIL0dYzClwCMikqfIchFVnvffyEZsCldbxNpc/e6gjdDihmkcdx5S2/iqi+JUr0dEGYLk9nfVUvb87gD/kdUddH7ZBVWdvBnDgsGMarzZy2ZqfC1NIkbfrOIJTCCFA5XJPcFNmQlOMBwHUUF4KdshD48VXfrChHLPFE/nZLC1idG5TEEU51bt8S1sl/HZ9XQhaUAASQ=" Sep 01 13:06:44 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:44+04: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]" Sep 01 13:06:44 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:44+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:45 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:45+04:00" level=debug msg="completed challenge" Sep 01 13:06:45 volumio-mbr go-librespot[27488]: time="2024-09-01T13:06:45+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:45 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:45 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:45 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:45 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:48 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:48 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:48 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:48 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222085. Sep 01 13:06:48 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:48 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 01 13:06:48 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:48 volumio-mbr go-librespot[27497]: Librespot-go daemon starting... Sep 01 13:06:48 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:48+04:00" level=info msg="generated new device id: 1474f94f66dde0bb1c9f57b922156a970a4bfc79" Sep 01 13:06:48 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:48+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:48 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:48+04:00" level=debug msg="obtained new client token: AAA9gjYVK1Dcx5bXxOf4nS0sBtkpcSMmi4qE/QNFT0A2La01hP+3Y5xA4V776lwpACagifEn0Ocl4hErjUCuU7Mv+QykTKa7JS07FL1t5/WR/5/1G1XoRJYHLxhEUNyNCA2VaLQ76t8MfplOuDYLIPG+9yZmqRgU3sUEnDFTOx8TXs036XmWAaf5uDpeMcgjLvhSQ3a7G7XCzJ/sb6Ylk0vBu+jKWt2QPXr8dq+QqoFzGLFLyEuKvb8UBGX9xA==" Sep 01 13:06:48 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:48+04: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]" Sep 01 13:06:49 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:49 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:49 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:49+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:49 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:49+04:00" level=debug msg="completed challenge" Sep 01 13:06:49 volumio-mbr go-librespot[27497]: time="2024-09-01T13:06:49+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:49 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:49 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:51 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:51 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:52 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:52 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222086. Sep 01 13:06:52 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:52 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:52 volumio-mbr go-librespot[27506]: Librespot-go daemon starting... Sep 01 13:06:52 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:52+04:00" level=info msg="generated new device id: 9e840f6183b9a2c2f50c76538404f6e68a3ad3b5" Sep 01 13:06:52 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:52+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:53 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:53+04:00" level=debug msg="obtained new client token: AADxnb11USPuAJy+7J/7ovITe2J+VHLaDzlygHxlgb8CAD88rRaL98U/jabTc6A5mGkJyBa4+Blww+fZLGUgBrHD4/nd30Jr7PZaS4+NGQX7BcluwhrqcChiG2bqgeH2wu+0v6HB2IxD9zA4OuY87l733FR74otmsRUIJJAOrL53uGXigpdS0I6nlZkrQr/x1EqcwuYzauXSm8OhJzywhtLbrZDqSnGhEPvzzGfuVeoqimlSp2gqAAw/u7E=" Sep 01 13:06:53 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:53+04: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]" Sep 01 13:06:53 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:53+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:54 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:54+04:00" level=debug msg="completed challenge" Sep 01 13:06:54 volumio-mbr go-librespot[27506]: time="2024-09-01T13:06:54+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:54 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:54 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:54 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:54 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:57 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:06:57 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:06:57 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:06:57 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222087. Sep 01 13:06:57 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:06:57 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:06:57 volumio-mbr go-librespot[27514]: Librespot-go daemon starting... Sep 01 13:06:57 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:57+04:00" level=info msg="generated new device id: b384ccfca1da8ae033d29085be5851c0e8a5cc31" Sep 01 13:06:57 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:57+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:06:57 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:57+04:00" level=debug msg="obtained new client token: AAAJZ96VrMfOxm3dWJZGJlryC4zCJoSDefbdicJZZWH5DqOF9N4dPjG/uWfR2G0s/Ihn2+eRvWk7Ux3mbxLlDqLBMzNdnG6LQ6zm44BaqsRrfR98c8gEAQSWYo9GQ2pEWpURKowoJ/wvRvh1UVoo6++CZlJx4mX1oQrVuJl5H/kcFOUEIIAACWOHMyXX4eUvHlonl75z+Y4SczpU2XbY5ifMqFAszORH9+4y9I/2vil1Xlvqn9VDy9aUJ1vQIw==" Sep 01 13:06:57 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:06:57 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:06:57 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:06:57 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:57 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:57 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:06:57 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:57+04: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]" Sep 01 13:06:58 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:58+04:00" level=debug msg="completed keyexchange" Sep 01 13:06:58 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:58+04:00" level=debug msg="completed challenge" Sep 01 13:06:58 volumio-mbr go-librespot[27514]: time="2024-09-01T13:06:58+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:06:58 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:06:58 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:06:59 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:06:59 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:06:59 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:06:59 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:07:00 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:00 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:01 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:01 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222088. Sep 01 13:07:01 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:01 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:01 volumio-mbr go-librespot[27523]: Librespot-go daemon starting... Sep 01 13:07:01 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:01+04:00" level=info msg="generated new device id: 98583be29e5f79a7ff4c7317e98aa01789d2d825" Sep 01 13:07:01 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:01+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:02 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:02+04:00" level=debug msg="obtained new client token: AABFfx82bnFQqleG6Lk757z7XpeoCRMwEmzOPtsmJhNS+xa4IP6+w13JJ5/NPCk8o40K2jBgz+aE7ETFF98whBrJNsgFCQbCW4QGrca8IoY1FW/80dEkGo9TTcXem6e29oXR0h9J8fobEe+oxrW4DHlsnd8bPSAfRTknrF+WFam5vx8DOAm7HWeR7T1qcB0wLVRrxtqra2mS7cjJ5c92vICX+u7d6AROx3qhbGxkZBBnWhFl/l3bTNE8QiI=" Sep 01 13:07:02 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:02+04: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]" Sep 01 13:07:02 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:02+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:03 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:03+04:00" level=debug msg="completed challenge" Sep 01 13:07:03 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:03 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:03+04:00" level=debug msg="new websocket client" Sep 01 13:07:03 volumio-mbr volumio[831]: info: Connection to go-librespot Websocket established Sep 01 13:07:03 volumio-mbr go-librespot[27523]: time="2024-09-01T13:07:03+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:03 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:03 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:03 volumio-mbr volumio[831]: info: Connection to go-librespot Websocket closed Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:03 volumio-mbr volumio[831]: xcb_connection_has_error() returned true Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Sep 01 13:07:03 volumio-mbr volumio[831]: info: Getting Alsa Cards List without I2S DAC Sep 01 13:07:03 volumio-mbr volumio[831]: xcb_connection_has_error() returned true Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: xcb_connection_has_error() returned true Sep 01 13:07:03 volumio-mbr volumio[831]: xcb_connection_has_error() returned true Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Sep 01 13:07:03 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 01 13:07:06 volumio-mbr volumio[831]: info: Getting Spotify volume Sep 01 13:07:06 volumio-mbr volumio[831]: (node:831) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:06 volumio-mbr volumio[831]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 01 13:07:06 volumio-mbr volumio[831]: (node:831) 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: 21467) Sep 01 13:07:06 volumio-mbr volumio[831]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Sep 01 13:07:06 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:06 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:06 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:06 volumio-mbr volumio[831]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Sep 01 13:07:06 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:06 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:06 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222089. Sep 01 13:07:06 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:06 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:06 volumio-mbr go-librespot[27539]: Librespot-go daemon starting... Sep 01 13:07:06 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:06+04:00" level=info msg="generated new device id: 8b282cad0ca8e619a654b818914367942e2e6dcf" Sep 01 13:07:06 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:06+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:06 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:06+04:00" level=debug msg="obtained new client token: AABJ+1+AuX9/uBypr26umSMeEhCT0FYacY1QxT1fm/kb2ZciX1JvFGEHhfx5eaJX3wkuQEZzPu1O1JVrLJRNg08Hl8rLKz5aKQch4gR34EKu2C1i5L/i/uU4AteGslbLACqhevk2w1faiCa6Wq61fxfRUB+OoS6usp1vWDQ8kp78Pldk7PfPPTzbgQMxP3wBeNXcc4C/my5204EiPt5BGcUVPj2Wp8M0hvecPoFA0GNXngyRXDJYEFwn8iYzgQ==" Sep 01 13:07:06 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:06+04: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]" Sep 01 13:07:07 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:07+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:07 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:07+04:00" level=debug msg="completed challenge" Sep 01 13:07:07 volumio-mbr go-librespot[27539]: time="2024-09-01T13:07:07+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:07 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:07 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:09 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:09 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:09 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:09 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:10 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:10 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222090. Sep 01 13:07:10 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:10 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:10 volumio-mbr go-librespot[27551]: Librespot-go daemon starting... Sep 01 13:07:10 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:10+04:00" level=info msg="generated new device id: dc558e87e5d39b63d907074b71fcc673bfa99cf4" Sep 01 13:07:10 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:10+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:11 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:11+04:00" level=debug msg="obtained new client token: AAA7lc9xWXXDM6r3MupGBQ5GPQTFS3sINgsdxPU0Xclghll6eD8vkwFQf65txViUdaMhDe3Aemc/x2JO6+FUKFXtWHx5H9V/k/TtpyL9+H2x3/QjxXZZo2luOhjy0Ooaj6vkh/4IwLeK8jvEA0pUNeE/3L60XmRmz3+F6MfUGCO1Bt1psCdzU2tP7PFG9HQUEZmsV2BR9Z4CM3P4MUoYh/SdNIjhKYkF7AWx1vWODK1TdWVGWRyiyotwQF0=" Sep 01 13:07:11 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:11+04: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]" Sep 01 13:07:11 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:11+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:12 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:12+04:00" level=debug msg="completed challenge" Sep 01 13:07:12 volumio-mbr go-librespot[27551]: time="2024-09-01T13:07:12+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:12 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:12 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:12 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:12 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:15 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:15 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222091. Sep 01 13:07:15 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:15 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:15 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:15 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:15 volumio-mbr go-librespot[27559]: Librespot-go daemon starting... Sep 01 13:07:15 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:15+04:00" level=info msg="generated new device id: 16bd5e6b98606644f2657e836df17403911b4911" Sep 01 13:07:15 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:15+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:15 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:15+04:00" level=debug msg="obtained new client token: AACL+nBwLNwd+r5sqVBXB3Q4QM4EUabW27NCWSJrNyybnjPQNiNymI6kqaanmLvM9BvaluxAAwFPw056bwob9MSvmjhYBRsrIb4lwozltw/MLk7/GBwZG5Sg59NZbwy4Ni3Yv+JjxakZAW0hZ/9jwBl1uDmMjTJsBqzrP+9SeYHtfWXRdwhWHlskVK6mhK2BclJxeAFeo+EhR559JJDOmuXguYJ77U9SGqrUMM09lMsy3vtGBwLCbVyPp0k4Uw==" Sep 01 13:07:15 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Sep 01 13:07:15 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:15+04: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]" Sep 01 13:07:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Sep 01 13:07:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Sep 01 13:07:15 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Sep 01 13:07:16 volumio-mbr volumio[831]: info: Received Get System Version Sep 01 13:07:16 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 13:07:16 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:16+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:16 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:16+04:00" level=debug msg="completed challenge" Sep 01 13:07:16 volumio-mbr go-librespot[27559]: time="2024-09-01T13:07:16+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:16 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:16 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:18 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:18 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:19 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:19 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:19 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:07:19 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:07:19 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:19 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222092. Sep 01 13:07:19 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:19 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:19 volumio-mbr go-librespot[27581]: Librespot-go daemon starting... Sep 01 13:07:19 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:19+04:00" level=info msg="generated new device id: a08306d0b9cb34d278002bc887cf279684a44134" Sep 01 13:07:19 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:19+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:20 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:20+04:00" level=debug msg="obtained new client token: AADDCYgf6AtozL4bHmWRX+XCmOe8I9iwh7sihn8BgMaMw4ACPr39aERLmsr6ly4e8Umq5yGLxEAqq5GjVrz3LZqPjEXkfufHi9Q1hEmJaCwTsb/g+o4eMV/NZYMDMcqdvjlsR5crAdeZcqBAwLvLsQHgDWmGL5CCGB1pRBXDaQDlCkOBmsqf5Cwhr4KYRw+D9d9/i6nOpQ5edd48IjV/vKS3uLObJy5c6RncOfqCq40tL5TzLDrqP5Lw/T8=" Sep 01 13:07:20 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:20+04: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]" Sep 01 13:07:20 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:20+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:21 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:21+04:00" level=debug msg="completed challenge" Sep 01 13:07:21 volumio-mbr go-librespot[27581]: time="2024-09-01T13:07:21+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:21 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:21 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:21 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:21 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:24 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:24 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222093. Sep 01 13:07:24 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:24 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:24 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:24 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:24 volumio-mbr go-librespot[27627]: Librespot-go daemon starting... Sep 01 13:07:24 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:24+04:00" level=info msg="generated new device id: 9ed15c014ca096156bbf24a6b726063f955eaaa2" Sep 01 13:07:24 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:24+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:24 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:24+04:00" level=debug msg="obtained new client token: AAAUCnBRD6xXYGwhD24vTR1MLG3uqeGDYg4J4vvMicDYUmjl4+w9FKJWn4GD4cAxI4P5aFH+Zmcyq7BzE91UmPkAV7uBLzVZV8rPEu+YWlTtcg2chjrKHN8beq+z8tG8FtAIetrN6N743BPu8J0FCsczLl3xhRHN1R5svH0y8eS8WSBPn9DQw+lSNbtU3XvvdwxZJWFx+DGj8sPxuKPsaM1lPAL4GKg3PSiYA25rs6KpF5+TPfkhhCRRaUrm3Q==" Sep 01 13:07:24 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:24+04: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]" Sep 01 13:07:25 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:25+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:25 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:25+04:00" level=debug msg="completed challenge" Sep 01 13:07:25 volumio-mbr go-librespot[27627]: time="2024-09-01T13:07:25+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:25 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:25 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:27 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:27 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 13:07:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 13:07:27 volumio-mbr volumio[831]: info: Discovery: Getting this device information Sep 01 13:07:27 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:27 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:27 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 13:07:28 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:28 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222094. Sep 01 13:07:28 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:28 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:28 volumio-mbr go-librespot[27635]: Librespot-go daemon starting... Sep 01 13:07:28 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:28+04:00" level=info msg="generated new device id: 990de62ced95b61e2f1361dd9f05eef7cb544972" Sep 01 13:07:28 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:28+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:29 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:29 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:29+04:00" level=debug msg="obtained new client token: AACxmCw+FrZ4jlQ2GOzZKgMIgJM7iX2AH6bhqfS3BsqiZ6Jb5vDCT725jBknQBVBvqw+kDt4QtijbDrf93kXv1uce7+xj3nvoWuFJ2vu9gTolNiJNX2QIrfCjjqLerMHK7AWPQPGzvdaGeIyoPcRSwltK9atSl9NQJ7nmiP+tsxK9K65zks2HmPp77NlAT8gDR0l3jp5BUcBF7WWTNd8S5ZhrqsfbLo+QoxdhumhjPoxmvdRgsJDRgvfhIs=" Sep 01 13:07:29 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:29+04: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]" Sep 01 13:07:29 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:29+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: Retrieving Cloud Streaming UI Sep 01 13:07:29 volumio-mbr volumio[831]: info: Getting Tidal Cloud Configuration Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: Getting Qobuz Cloud Configuration Sep 01 13:07:29 volumio-mbr volumio[831]: info: Asking plugin for UI Config Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: Getting Spotify Cloud Configuration Sep 01 13:07:29 volumio-mbr volumio[831]: info: Asking plugin for UI Config Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: Saving Spotify Acccount Sep 01 13:07:29 volumio-mbr volumio[831]: info: Got it Sep 01 13:07:29 volumio-mbr volumio[831]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Sep 01 13:07:29 volumio-mbr volumio[831]: info: Got Tidal Cloud Configuration Sep 01 13:07:29 volumio-mbr volumio[831]: info: Got it Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Sep 01 13:07:29 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Sep 01 13:07:30 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:30+04:00" level=debug msg="completed challenge" Sep 01 13:07:30 volumio-mbr go-librespot[27635]: time="2024-09-01T13:07:30+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:30 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:30 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:30 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:30 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:33 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:33 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222095. Sep 01 13:07:33 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:33 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:33 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:33 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:33 volumio-mbr go-librespot[27648]: Librespot-go daemon starting... Sep 01 13:07:33 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:33+04:00" level=info msg="generated new device id: 5ac94a87ec9c58fb144a500cdbdd4fae6b339d13" Sep 01 13:07:33 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:33+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:33 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:33+04:00" level=debug msg="obtained new client token: AACHMB3mPtjZQshsynabDiljp/ncykeBmLlRoxBCaztjJ53a9D0uB9tCZDjGKDPMnrfy+NLbTvegF8dFQt0lnS9+OJ0fham5WdCFxzNnWAfGwYCzshV5CPvwLlIVesJ1Kp/ljj7AYp6+ZnMF09WjZUIx8wBH6llC1S/QM75EFnG0ipMxiTxmXwo4QpNyuas3/O13oll3MTDxMy8nqBNJNvGPX5GzymjqAstqAOTfjusufNX2ugcuLzX2eVTVMA==" Sep 01 13:07:33 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:33+04: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]" Sep 01 13:07:34 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:34+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:34 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:34+04:00" level=debug msg="completed challenge" Sep 01 13:07:34 volumio-mbr go-librespot[27648]: time="2024-09-01T13:07:34+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:34 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:34 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:34 volumio-mbr volumio[831]: info: Retrieving Cloud Streaming UI Sep 01 13:07:34 volumio-mbr volumio[831]: info: Getting Tidal Cloud Configuration Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:34 volumio-mbr volumio[831]: info: Getting Qobuz Cloud Configuration Sep 01 13:07:34 volumio-mbr volumio[831]: info: Asking plugin for UI Config Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:34 volumio-mbr volumio[831]: info: Getting Spotify Cloud Configuration Sep 01 13:07:34 volumio-mbr volumio[831]: info: Asking plugin for UI Config Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:34 volumio-mbr volumio[831]: info: Saving Spotify Acccount Sep 01 13:07:34 volumio-mbr volumio[831]: info: Got it Sep 01 13:07:34 volumio-mbr volumio[831]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Sep 01 13:07:34 volumio-mbr volumio[831]: info: Got Tidal Cloud Configuration Sep 01 13:07:34 volumio-mbr volumio[831]: info: Got it Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetBrowseSources Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Sep 01 13:07:34 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Sep 01 13:07:36 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:36 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:37 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:37 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222096. Sep 01 13:07:37 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:37 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:37 volumio-mbr go-librespot[27660]: Librespot-go daemon starting... Sep 01 13:07:37 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:37+04:00" level=info msg="generated new device id: df2a43aca24e7227bd4f54523b847ea07e72220a" Sep 01 13:07:37 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:37+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:38 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:38+04:00" level=debug msg="obtained new client token: AACgry8AXvPYQ/AzNkkwaJRfMsQ1K/9z3srpQsFrofDxLqmlj3nU34w+MQmWxAycPIsD3vbFTrlbKgg9YjWaJf80vIDOXr4NxQAkh5ZE9CjTGAYO13lHfjfvWqnEuSrNpCObVZ4aLwrn6McUrdPkqT2O4JpAQ6ikxDAMrK8L6MjtuDUm0X2ANATaH7yp2vhXHZe3X7YucY8HCUr5/ZDBsO3V3W5b+WOLb5XRHnnKfnzqIM9hiNPcsM28yRU=" Sep 01 13:07:38 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:38+04: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]" Sep 01 13:07:38 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:38+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:39 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:39 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:39 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:07:39 volumio-mbr volumio[831]: info: Listing playlists Sep 01 13:07:39 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:39+04:00" level=debug msg="completed challenge" Sep 01 13:07:39 volumio-mbr go-librespot[27660]: time="2024-09-01T13:07:39+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:39 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:39 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:39 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:39 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:42 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:42 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222097. Sep 01 13:07:42 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:42 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:42 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:42 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:42 volumio-mbr go-librespot[27669]: Librespot-go daemon starting... Sep 01 13:07:42 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:42+04:00" level=info msg="generated new device id: f0303a89fd2ec464ae550dc33f943660e33087cd" Sep 01 13:07:42 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:42+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:42 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:42+04:00" level=debug msg="obtained new client token: AACFla0Yb1shD1QsLUVPARXSAF2w2Z0nLvj+c9AhFZ7ruHsqUZaLaSX25h1kL+gG3PD9M9kFom79GITp5gARapZxtFRCfLln3Qt8v/45MrmsjtS3JGgJoXXqkUwxPwNr4rsIputoy5BFV4i4y2Egx38cazCuY29XF4iqXksMg4gvn+JX5Dm0rBnRDUDWwo+0WJ4kCqTr1CwlV5+ANoI9tBFfdoE44o41tjwGF9UywGLtXZKK2h8HmUkVGbJg1w==" Sep 01 13:07:42 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:42+04: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]" Sep 01 13:07:43 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:43+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:43 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:43+04:00" level=debug msg="completed challenge" Sep 01 13:07:43 volumio-mbr go-librespot[27669]: time="2024-09-01T13:07:43+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:43 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:43 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:45 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:45 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:46 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:46 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222098. Sep 01 13:07:46 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:46 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:46 volumio-mbr go-librespot[27678]: Librespot-go daemon starting... Sep 01 13:07:46 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:46+04:00" level=info msg="generated new device id: cac376afba870046f29c45be8d2552146f982c8e" Sep 01 13:07:46 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:46+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:47 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:47+04:00" level=debug msg="obtained new client token: AAATP1TjeODlCOlN9VSkcTz2Q48kHhTk34sXNzIYq+MkFWtMSymhD5LP+8qIxKaAfpxhcoJAl857l4opJVocKW8vIUfG+ncvh+OLfAv7l4Bj7e/EFk1iF2G6Ap39rmIvHDiI6jTlZos1E3F7m0juux1DVreVlbbw0+4a9bL2bK3KeSWQy/CWk4+tnlgkXQU60v79yz1A39WRQHp2YL+naO31/+v/lLi3qnU1JEkA1F4pXw5kx8s2f9fYgUU=" Sep 01 13:07:47 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:47+04: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]" Sep 01 13:07:47 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:47+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:48 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:48+04:00" level=debug msg="completed challenge" Sep 01 13:07:48 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 01 13:07:48 volumio-mbr go-librespot[27678]: time="2024-09-01T13:07:48+04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 01 13:07:48 volumio-mbr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 13:07:48 volumio-mbr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 13:07:48 volumio-mbr volumio[831]: info: Preload queue cleared Sep 01 13:07:48 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:48 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:49 volumio-mbr volumio[831]: info: CoreCommandRouter::volumioGetState Sep 01 13:07:49 volumio-mbr volumio[831]: info: CorePlayQueue::getTrack 0 Sep 01 13:07:49 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 01 13:07:49 volumio-mbr volumio[831]: info: Preload queue cleared Sep 01 13:07:50 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 01 13:07:50 volumio-mbr volumio[831]: info: Preload queue cleared Sep 01 13:07:51 volumio-mbr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 13:07:51 volumio-mbr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 222099. Sep 01 13:07:51 volumio-mbr systemd[1]: Stopped go-librespot Daemon. Sep 01 13:07:51 volumio-mbr volumio[831]: info: Initializing connection to go-librespot Websocket Sep 01 13:07:51 volumio-mbr volumio[831]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 13:07:51 volumio-mbr systemd[1]: Started go-librespot Daemon. Sep 01 13:07:51 volumio-mbr go-librespot[27687]: Librespot-go daemon starting... Sep 01 13:07:51 volumio-mbr go-librespot[27687]: time="2024-09-01T13:07:51+04:00" level=info msg="generated new device id: e867feac6169c702ab93c3df5d29c28e82d8f75f" Sep 01 13:07:51 volumio-mbr go-librespot[27687]: time="2024-09-01T13:07:51+04:00" level=debug msg="stored credentials found for m3ox5g67sbzsptg5zivbzbmzz" Sep 01 13:07:51 volumio-mbr go-librespot[27687]: time="2024-09-01T13:07:51+04:00" level=debug msg="obtained new client token: AAB/eXF8Y1WJq9ncVbXCGsfbXE60lpfmC6ni3LEq7xvB2ElWZugdogdJFfg/zh++7AtRr7E5JXUlOCtMrJHDCSGGTbzG6XWcwoSBVMHpoqy2ifpKIQl39jWc+EqthGryjlUHnbqsNd5btY0yt/uFNnPZ5ub6EF+jKvnAVcodSScWUiTE+8RJnJbaodYBI4myT8sMPDyovwUi4YlC5GMTV/7ULVOrCcBWKDu82pWkgKXNYAdLGylFDUmVMQEfBg==" Sep 01 13:07:51 volumio-mbr volumio[831]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 01 13:07:51 volumio-mbr volumio[831]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 13:07:51 volumio-mbr volumio[831]: TypeError: Cannot read property 'length' of undefined Sep 01 13:07:51 volumio-mbr volumio[831]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Sep 01 13:07:51 volumio-mbr volumio[831]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Sep 01 13:07:51 volumio-mbr volumio[831]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Sep 01 13:07:51 volumio-mbr volumio[831]: at Parser.emit (events.js:315:20) Sep 01 13:07:51 volumio-mbr volumio[831]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Sep 01 13:07:51 volumio-mbr volumio[831]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Sep 01 13:07:51 volumio-mbr volumio[831]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Sep 01 13:07:51 volumio-mbr volumio[831]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Sep 01 13:07:51 volumio-mbr volumio[831]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Sep 01 13:07:51 volumio-mbr volumio[831]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Sep 01 13:07:51 volumio-mbr volumio[831]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Sep 01 13:07:51 volumio-mbr volumio[831]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Sep 01 13:07:51 volumio-mbr volumio[831]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Sep 01 13:07:51 volumio-mbr volumio[831]: at IncomingMessage.emit (events.js:327:22) Sep 01 13:07:51 volumio-mbr volumio[831]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 01 13:07:51 volumio-mbr volumio[831]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 01 13:07:51 volumio-mbr volumio[831]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 13:07:51 volumio-mbr go-librespot[27687]: time="2024-09-01T13:07:51+04: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]" Sep 01 13:07:52 volumio-mbr go-librespot[27687]: time="2024-09-01T13:07:52+04:00" level=debug msg="completed keyexchange" Sep 01 13:07:52 volumio-mbr sudo[27704]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-01 13:06 Sep 01 13:07:52 volumio-mbr sudo[27704]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"