-- Logs begin at Sat 2025-01-18 20:34:37 +05, end at Sat 2025-01-18 23:18:27 +05. -- Jan 18 23:17:01 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:01 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5921. Jan 18 23:17:01 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:01 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:01 volumio go-librespot[28078]: Librespot-go daemon starting... Jan 18 23:17:01 volumio go-librespot[28078]: time="2025-01-18T23:17:01+05:00" level=info msg="generated new device id: 4347b32964338aa4262389be6726e77746ed8e66" Jan 18 23:17:01 volumio go-librespot[28078]: time="2025-01-18T23:17:01+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:02 volumio go-librespot[28078]: time="2025-01-18T23:17:02+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:02 volumio go-librespot[28078]: time="2025-01-18T23:17:02+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:02 volumio go-librespot[28078]: time="2025-01-18T23:17:02+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:02 volumio go-librespot[28078]: time="2025-01-18T23:17:02+05:00" level=debug msg="zeroconf server listening on port 40381" Jan 18 23:17:03 volumio go-librespot[28078]: time="2025-01-18T23:17:03+05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": EOF" Jan 18 23:17:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:04 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:04 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:05 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:05 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:05 volumio volumio[954]: verbose: New Socket.io Connection to 192.168.68.130:3000 from 192.168.68.134 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:05 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 18 23:17:05 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 18 23:17:05 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 18 23:17:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5922. Jan 18 23:17:07 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:07 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:07 volumio go-librespot[28104]: Librespot-go daemon starting... Jan 18 23:17:07 volumio go-librespot[28104]: time="2025-01-18T23:17:07+05:00" level=info msg="generated new device id: cc6644e8e023440704c728e65e77c3388e4a830b" Jan 18 23:17:07 volumio go-librespot[28104]: time="2025-01-18T23:17:07+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:07 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:07 volumio go-librespot[28104]: time="2025-01-18T23:17:07+05:00" level=debug msg="new websocket client" Jan 18 23:17:07 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=debug msg="zeroconf server listening on port 35323" Jan 18 23:17:08 volumio sudo[28114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 18 23:17:08 volumio sudo[28114]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:17:08 volumio sudo[28114]: pam_unix(sudo:session): session closed for user root Jan 18 23:17:08 volumio sudo[28116]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 18 23:17:08 volumio sudo[28116]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:17:08 volumio sudo[28116]: pam_unix(sudo:session): session closed for user root Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=debug msg="obtained new client token: AAB05oRhmz03L1xUdDNA8HAVzf3R15pbNlMHVH0oA71YSXsr4nPW+ZWgbZIUvFzWamdiRo7ePlwnDuYPqlanbOL+X1hM83wYWcql16qZc+48jLN75GU3RLu2bgnlalHIQUs7YBLW9MiwkyJ2NXnViUwk9iaTPmh1R4FrWhQb/NEHJ4bcvOOIhMbjHHwUJE3SZfML2S+bEsKhdTum0XUOEgQJKl/le8PSr5rjY7F866C6BgwtNl+WqbDUn6e9Xeo=" Jan 18 23:17:08 volumio volumio[954]: verbose: New Socket.io Connection to 192.168.68.130 from 192.168.68.134 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Jan 18 23:17:08 volumio go-librespot[28104]: time="2025-01-18T23:17:08+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:08 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 18 23:17:09 volumio sudo[28121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 18 23:17:09 volumio sudo[28121]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:17:09 volumio sudo[28121]: pam_unix(sudo:session): session closed for user root Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 18 23:17:09 volumio sudo[28124]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 18 23:17:09 volumio sudo[28124]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:17:09 volumio sudo[28124]: pam_unix(sudo:session): session closed for user root Jan 18 23:17:09 volumio go-librespot[28104]: time="2025-01-18T23:17:09+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:09 volumio volumio[954]: verbose: New Socket.io Connection to 192.168.68.130 from 192.168.68.134 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::volumioGetVisibleSources Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:09 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 18 23:17:09 volumio volumio[954]: info: Received Get System Info Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:09 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:09 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:09 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:09 volumio volumio[954]: info: Listing playlists Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 18 23:17:09 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 18 23:17:09 volumio go-librespot[28104]: time="2025-01-18T23:17:09+05:00" level=debug msg="completed challenge" Jan 18 23:17:09 volumio go-librespot[28104]: time="2025-01-18T23:17:09+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:09 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:17:10 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:17:10 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:10 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:17:10 volumio volumio[954]: (node:954) 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: 3487) Jan 18 23:17:10 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:10 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:10 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 18 23:17:10 volumio volumio[954]: info: Received Get System Info Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:10 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:10 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:10 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:11 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:11 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:11 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:12 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:17:12 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:17:12 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:17:12 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:12 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:17:12 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:12 volumio volumio[954]: info: [1737224232775] ControllerSpotify::clearAddPlayTrack Jan 18 23:17:12 volumio volumio[954]: info: Sending Spotify command with payload to local API: /player/play Jan 18 23:17:12 volumio volumio[954]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:12 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:12 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5923. Jan 18 23:17:13 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:13 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:13 volumio go-librespot[28180]: Librespot-go daemon starting... Jan 18 23:17:13 volumio go-librespot[28180]: time="2025-01-18T23:17:13+05:00" level=info msg="generated new device id: 79553466299fdeb034c616c2c4737499ec5489f5" Jan 18 23:17:13 volumio go-librespot[28180]: time="2025-01-18T23:17:13+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:14 volumio go-librespot[28180]: time="2025-01-18T23:17:14+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:14 volumio go-librespot[28180]: time="2025-01-18T23:17:14+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:14 volumio go-librespot[28180]: time="2025-01-18T23:17:14+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:15 volumio go-librespot[28180]: time="2025-01-18T23:17:15+05:00" level=debug msg="zeroconf server listening on port 41509" Jan 18 23:17:15 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:15 volumio go-librespot[28180]: time="2025-01-18T23:17:15+05:00" level=debug msg="new websocket client" Jan 18 23:17:15 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:17:16 volumio kernel: hwmon hwmon1: Voltage normalised Jan 18 23:17:18 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:17:18 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 18 23:17:18 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:18 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:18 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:17:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 18 23:17:23 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:17:23 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:17:23 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:23 volumio volumio[954]: info: [1737224243080] ControllerSpotify::clearAddPlayTrack Jan 18 23:17:23 volumio volumio[954]: info: Sending Spotify command with payload to local API: /player/play Jan 18 23:17:23 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:17:23 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:23 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:17:23 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:23 volumio volumio[954]: info: [1737224243809] ControllerSpotify::clearAddPlayTrack Jan 18 23:17:23 volumio volumio[954]: info: Sending Spotify command with payload to local API: /player/play Jan 18 23:17:25 volumio go-librespot[28180]: time="2025-01-18T23:17:25+05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": net/http: TLS handshake timeout" Jan 18 23:17:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:25 volumio volumio[954]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jan 18 23:17:25 volumio volumio[954]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jan 18 23:17:25 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: socket hang up Jan 18 23:17:25 volumio volumio[954]: at connResetException (internal/errors.js:607:14) Jan 18 23:17:25 volumio volumio[954]: at Socket.socketOnEnd (_http_client.js:493:23) Jan 18 23:17:25 volumio volumio[954]: at Socket.emit (events.js:327:22) Jan 18 23:17:25 volumio volumio[954]: at endReadableNT (internal/streams/readable.js:1327:12) Jan 18 23:17:25 volumio volumio[954]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jan 18 23:17:25 volumio volumio[954]: (node:954) 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: 3488) Jan 18 23:17:25 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 18 23:17:27 volumio volumio[954]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jan 18 23:17:27 volumio volumio[954]: info: Received Get System Version Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 18 23:17:27 volumio volumio[954]: info: Received Get System Info Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:27 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:27 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:27 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:28 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:28 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5924. Jan 18 23:17:28 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:28 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:28 volumio go-librespot[28209]: Librespot-go daemon starting... Jan 18 23:17:28 volumio go-librespot[28209]: time="2025-01-18T23:17:28+05:00" level=info msg="generated new device id: 687186c99ba0185565a40708a2552cba8b24b856" Jan 18 23:17:28 volumio go-librespot[28209]: time="2025-01-18T23:17:28+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:28 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 18 23:17:29 volumio volumio[954]: info: Received Get System Info Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:29 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:29 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 18 23:17:29 volumio volumio[954]: info: Received Get System Info Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:29 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:29 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:29 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:31 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:31 volumio go-librespot[28209]: time="2025-01-18T23:17:31+05:00" level=debug msg="new websocket client" Jan 18 23:17:31 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="zeroconf server listening on port 44461" Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="obtained new client token: AACM/SgL+53Fk9sav1tF6Pqz9W/5e3GM67oaCaqD6mTtB2kutHhu1FwawQG6FazxQhmBTHCm+MDhbcr3w9hWNdNb40/BBpJsdTZyro1vby6QTXY7Iz8dDHuXUpInX1GvxvakfpjrqT2rOqmqmRkeJWtCPE7TvLlVks7Vi2V+Zscu+JDQ5SjxokKaPUQ3aM6mnhxRgKFdT05zEkE/ZuCZS19VxXNiTremHEVQ/ZGeAeWJHazEhsO41HvbdK/GCVQ=" Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:32 volumio kernel: hwmon hwmon1: Voltage normalised Jan 18 23:17:32 volumio go-librespot[28209]: time="2025-01-18T23:17:32+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:33 volumio volumio[954]: error: Failed to check for new versions for plugin YouTube Music: Error: Invalid argument not valid semver ('' received) Jan 18 23:17:33 volumio go-librespot[28209]: time="2025-01-18T23:17:33+05:00" level=debug msg="completed challenge" Jan 18 23:17:33 volumio go-librespot[28209]: time="2025-01-18T23:17:33+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:33 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:17:34 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:17:34 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:34 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:17:34 volumio volumio[954]: (node:954) 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: 3489) Jan 18 23:17:34 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 18 23:17:34 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:34 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:34 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:17:34 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:17:34 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:17:34 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:17:34 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:34 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:34 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:17:36 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:36 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5925. Jan 18 23:17:36 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:36 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:36 volumio go-librespot[28237]: Librespot-go daemon starting... Jan 18 23:17:36 volumio go-librespot[28237]: time="2025-01-18T23:17:36+05:00" level=info msg="generated new device id: 84706ee0317992df764b109c92308d3051766c06" Jan 18 23:17:36 volumio go-librespot[28237]: time="2025-01-18T23:17:36+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:37 volumio go-librespot[28237]: time="2025-01-18T23:17:37+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:37 volumio go-librespot[28237]: time="2025-01-18T23:17:37+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:37 volumio go-librespot[28237]: time="2025-01-18T23:17:37+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:37 volumio go-librespot[28237]: time="2025-01-18T23:17:37+05:00" level=debug msg="zeroconf server listening on port 36083" Jan 18 23:17:38 volumio go-librespot[28237]: time="2025-01-18T23:17:38+05:00" level=debug msg="obtained new client token: AADLV6y/vjRGhGBlz+68pgEaH5rS5ZbC9ZkJr3E0AtojB/fl4YRVgdqm6KQuj9yJ1X47XwHjeVQnLwhHHZvZSoqbwe1ZyUAP4XUD0COGlX8i+7GUpNpdDWIY9/qiYTpbTVfZkO7Om41tdpsrAXyM1I76KhYz81SXoLaY5tEGbc4obFPREMSANvV883fJ7RTgjZq3JhlxODEn630PhLxZW8rpe+xd02g5QjYXcJbwZ+LxL5Q5c1UtWat8zNqOVLY=" Jan 18 23:17:38 volumio volumio[954]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/touch_display/volumio/buster/armhf Jan 18 23:17:38 volumio go-librespot[28237]: time="2025-01-18T23:17:38+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:38 volumio go-librespot[28237]: time="2025-01-18T23:17:38+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:39 volumio go-librespot[28237]: time="2025-01-18T23:17:39+05:00" level=debug msg="completed challenge" Jan 18 23:17:39 volumio go-librespot[28237]: time="2025-01-18T23:17:39+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:39 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:39 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:40 volumio volumio[954]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/touch_display/volumio/buster/armhf Jan 18 23:17:40 volumio volumio[954]: info: Folder /tmp/plugins removed Jan 18 23:17:40 volumio volumio[954]: info: Check plugin dependencies Jan 18 23:17:40 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 18 23:17:40 volumio volumio[954]: info: Checking if plugin already exists Jan 18 23:17:40 volumio volumio[954]: info: Rename folder Jan 18 23:17:40 volumio volumio[954]: info: Folder /tmp/downloaded_plugin.zip removed Jan 18 23:17:40 volumio volumio[954]: info: Move to category Jan 18 23:17:41 volumio volumio[954]: info: Checking if install.sh is present Jan 18 23:17:41 volumio volumio[954]: info: Executing install.sh Jan 18 23:17:41 volumio sudo[28259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/user_interface/touch_display/install.sh Jan 18 23:17:41 volumio sudo[28259]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:17:41 volumio volumio[954]: info: Re-synchronizing package index files from their sources Jan 18 23:17:41 volumio volumio[954]: info: Get:1 http://raspbian.raspberrypi.org/raspbian buster InRelease [15.0 kB] Jan 18 23:17:41 volumio volumio[954]: info: Hit:2 http://archive.raspberrypi.org/debian buster InRelease Jan 18 23:17:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5926. Jan 18 23:17:42 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:42 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:42 volumio go-librespot[28309]: Librespot-go daemon starting... Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=info msg="generated new device id: aab374a8d7d39251ed18647250f74092353ef0f1" Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:42 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="new websocket client" Jan 18 23:17:42 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:42 volumio go-librespot[28309]: time="2025-01-18T23:17:42+05:00" level=debug msg="zeroconf server listening on port 44693" Jan 18 23:17:43 volumio go-librespot[28309]: time="2025-01-18T23:17:43+05:00" level=debug msg="obtained new client token: AAAP+2deG2uFsF1Vb2c4FqeK1HB+VmmTrHvh00MbCxr9KQQI9JjhVE8856PEAy2yhftoyP3etYLBFEo+8fMPRHHhYtvSrMSRxGEgXdzVRNoO6wvf4AHSqnlBMFBgIzQmKsoO7EVeDBY4QVxOZ74KgWlFaSf0XgXWUfWI7XlheuMqbFdTsWrDB+KFJdMZTz7Jkm8lLR7t5MzRJ+8himrT/PBU4w8uE99yqZ8CxhQ1LYRLCY0tYXGQxRn/7qKajgs=" Jan 18 23:17:43 volumio go-librespot[28309]: time="2025-01-18T23:17:43+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:43 volumio go-librespot[28309]: time="2025-01-18T23:17:43+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:44 volumio go-librespot[28309]: time="2025-01-18T23:17:44+05:00" level=debug msg="completed challenge" Jan 18 23:17:44 volumio go-librespot[28309]: time="2025-01-18T23:17:44+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:44 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:17:45 volumio volumio[954]: info: Hit:3 https://deb.nodesource.com/node_14.x buster InRelease Jan 18 23:17:45 volumio volumio[954]: info: Fetched 15.0 kB in 4s (3949 B/s) Jan 18 23:17:45 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:17:45 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:45 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:17:45 volumio volumio[954]: (node:954) 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: 3490) Jan 18 23:17:45 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:17:45 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:45 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:45 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:17:47 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:47 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5927. Jan 18 23:17:47 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:47 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:47 volumio go-librespot[28497]: Librespot-go daemon starting... Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=info msg="generated new device id: 4ef5b6b099ec0c55c7bca6c74718440626f8c977" Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:47 volumio go-librespot[28497]: time="2025-01-18T23:17:47+05:00" level=debug msg="zeroconf server listening on port 42881" Jan 18 23:17:50 volumio volumio[954]: info: Reading package lists... Jan 18 23:17:50 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:50 volumio go-librespot[28497]: time="2025-01-18T23:17:50+05:00" level=debug msg="new websocket client" Jan 18 23:17:50 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:17:51 volumio volumio[954]: info: Running apt-get -y install failed Jan 18 23:17:51 volumio volumio[954]: info: Plugin failed to install! Jan 18 23:17:51 volumio volumio[954]: info: Cleaning up... Jan 18 23:17:51 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 18 23:17:53 volumio systemd[1]: Reloading. Jan 18 23:17:53 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:17:53 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:17:53 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:17:53 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:17:53 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:17:53 volumio go-librespot[28497]: time="2025-01-18T23:17:53+05:00" level=debug msg="obtained new client token: AADojnqzE3Sk1g6BCVEIBHc6MFKW7zhTGx+C6LRbzD+ZIge4fFCbBhFHyofNPENd5bMY13QudXpOyCdNF7G6FVdvgMo+9Ae1Dp5/j8Pq7bBk+uYxCCBhpgpZeqdod33QkO4iQyilv5A7ZFAWRS0i1rXk7FLQooyDztWl4e1dxMVoKuJdLkdnhScROn6yqYocNEEvEepGpkmekixtqKXsQjyetxDaiXfDLLDB8bwdeTfKg6jZQjzpJPAeBmdYj9E=" Jan 18 23:17:53 volumio go-librespot[28497]: time="2025-01-18T23:17:53+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:53 volumio go-librespot[28497]: time="2025-01-18T23:17:53+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:53 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Jan 18 23:17:54 volumio go-librespot[28497]: time="2025-01-18T23:17:54+05:00" level=debug msg="completed challenge" Jan 18 23:17:54 volumio go-librespot[28497]: time="2025-01-18T23:17:54+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:54 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: socket hang up Jan 18 23:17:54 volumio volumio[954]: at connResetException (internal/errors.js:607:14) Jan 18 23:17:54 volumio volumio[954]: at Socket.socketOnEnd (_http_client.js:493:23) Jan 18 23:17:54 volumio volumio[954]: at Socket.emit (events.js:327:22) Jan 18 23:17:54 volumio volumio[954]: at endReadableNT (internal/streams/readable.js:1327:12) Jan 18 23:17:54 volumio volumio[954]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jan 18 23:17:54 volumio volumio[954]: (node:954) 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: 3491) Jan 18 23:17:54 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:17:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:17:54 volumio volumio[954]: info: Removing dependencies Jan 18 23:17:54 volumio volumio[954]: info: Deleting /opt/volumiokiosk.sh Jan 18 23:17:54 volumio volumio[954]: info: Deleting /data/volumiokiosk Jan 18 23:17:54 volumio volumio[954]: info: Deleting /data/volumiokioskextensions Jan 18 23:17:54 volumio volumio[954]: info: Deleting /lib/systemd/system/volumio-kiosk.service Jan 18 23:17:54 volumio systemd[1]: Starting Daily apt download activities... Jan 18 23:17:54 volumio volumio[954]: info: Enabling login prompt Jan 18 23:17:54 volumio volumio[954]: info: Done Jan 18 23:17:54 volumio volumio[954]: info: Removing plugin directory /data/plugins/user_interface/touch_display Jan 18 23:17:54 volumio volumio[954]: info: Removing temporary directory /tmp/touch_display-IBUr3Gt07X Jan 18 23:17:54 volumio sudo[28259]: pam_unix(sudo:session): session closed for user root Jan 18 23:17:54 volumio volumio[954]: info: Install script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/user_interface/touch_display/install.sh > /tmp/installog Jan 18 23:17:54 volumio volumio[954]: [sudo] password for volumio: E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem. Jan 18 23:17:54 volumio volumio[954]: E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem. Jan 18 23:17:54 volumio volumio[954]: rm: cannot remove '/opt/volumiokiosk.sh': No such file or directory Jan 18 23:17:54 volumio volumio[954]: rm: cannot remove '/lib/systemd/system/volumio-kiosk.service': No such file or directory Jan 18 23:17:54 volumio volumio[954]: info: An error occurred installing the plugin. Rolling back config Jan 18 23:17:54 volumio volumio[954]: info: Plugin folders cleanup Jan 18 23:17:54 volumio volumio[954]: info: Scanning into folder /volumio/app/plugins/ Jan 18 23:17:54 volumio volumio[954]: info: Scanning category audio_interface Jan 18 23:17:54 volumio volumio[954]: info: Scanning category miscellanea Jan 18 23:17:54 volumio volumio[954]: info: Scanning category music_service Jan 18 23:17:54 volumio volumio[954]: info: Scanning category plugins.json Jan 18 23:17:54 volumio volumio[954]: info: Scanning category system_controller Jan 18 23:17:54 volumio volumio[954]: info: Scanning category user_interface Jan 18 23:17:54 volumio volumio[954]: info: Scanning into folder /data/plugins/ Jan 18 23:17:54 volumio volumio[954]: info: Scanning category music_service Jan 18 23:17:54 volumio volumio[954]: info: Scanning category user_interface Jan 18 23:17:54 volumio volumio[954]: info: Plugin folders cleanup completed Jan 18 23:17:54 volumio volumio[954]: info: Error: Error Jan 18 23:17:54 volumio volumio[954]: info: Folder /tmp/plugins removed Jan 18 23:17:54 volumio volumio[954]: info: Folder /tmp/downloaded_plugin.zip removed Jan 18 23:17:54 volumio volumio[954]: Plugin install end detected on script Jan 18 23:17:54 volumio volumio[954]: info: Folder /data/temp removed Jan 18 23:17:55 volumio systemd[1]: apt-daily.service: Succeeded. Jan 18 23:17:55 volumio systemd[1]: Started Daily apt download activities. Jan 18 23:17:57 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:17:57 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:17:57 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:17:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5928. Jan 18 23:17:57 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:17:57 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:17:57 volumio go-librespot[28586]: Librespot-go daemon starting... Jan 18 23:17:57 volumio go-librespot[28586]: time="2025-01-18T23:17:57+05:00" level=info msg="generated new device id: 3a9c22dcec977ecc6260beb1dbb3849f790c20d6" Jan 18 23:17:57 volumio go-librespot[28586]: time="2025-01-18T23:17:57+05:00" level=debug msg="stored credentials not found" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=debug msg="zeroconf server listening on port 35831" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=debug msg="obtained new client token: AAByP4Pi1kv2mELfHctOX0S/M72a1u6DbnYhpz33/RXNwjMMiOhzbMa3dwIuKQJZXI/P4YR37YkOlbhDwcFvC/Xvaty1qDZP6j/KG1hhc2OcHy3vywIzmVvRud3vMZuWXoQY7eFrPXVKv83MtmygDgE+XlZVLzaPJgST/bkbmPD7JSqgoLXVGyR1h2iZ+RaJmOmwxsZMqOcXisUtxGDgpmdxMtg4ZB8n9HWo62+muzxYHJlBIPnzSiBD1JAepww=" Jan 18 23:17:58 volumio go-librespot[28586]: time="2025-01-18T23:17:58+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:17:59 volumio go-librespot[28586]: time="2025-01-18T23:17:59+05:00" level=debug msg="completed keyexchange" Jan 18 23:17:59 volumio go-librespot[28586]: time="2025-01-18T23:17:59+05:00" level=debug msg="completed challenge" Jan 18 23:17:59 volumio go-librespot[28586]: time="2025-01-18T23:17:59+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:17:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:17:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:18:00 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:00 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:02 volumio kernel: hwmon hwmon1: Voltage normalised Jan 18 23:18:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:18:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5929. Jan 18 23:18:03 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:18:03 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:18:03 volumio go-librespot[28595]: Librespot-go daemon starting... Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=info msg="generated new device id: 4ccb7a76a4c808302288f725bbc3896cb4b2bd70" Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="stored credentials not found" Jan 18 23:18:03 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="new websocket client" Jan 18 23:18:03 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:18:03 volumio go-librespot[28595]: time="2025-01-18T23:18:03+05:00" level=debug msg="zeroconf server listening on port 40757" Jan 18 23:18:04 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:18:04 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:18:04 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:04 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:04 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:18:04 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:04 volumio volumio[954]: info: [1737224284193] ControllerSpotify::clearAddPlayTrack Jan 18 23:18:04 volumio volumio[954]: info: Sending Spotify command with payload to local API: /player/play Jan 18 23:18:04 volumio go-librespot[28595]: time="2025-01-18T23:18:04+05:00" level=debug msg="obtained new client token: AABMZRkP7Wy0vElxpH3GNA5EUfr5VfzsLX5pfKiUnpXPPzoS7gh40dJPOFGz5W1E5SPBBxVcnokFL0vO1dYD1W9wOXxFAyHeMW7cpuW0PQENoO/5YjUfqL7X3FM26fk1XQLh1/Siou6qDgYT7Li7fhZcxYDlJ2A0OmPL/2CWoR4AizF3dzRGhULHSOSpCCEuuXv6e443DJPdDC8HvU1Ih4YDPu+phrowfgnZaDQ0G3cqjCradL3hLAFQCCUM" Jan 18 23:18:04 volumio go-librespot[28595]: time="2025-01-18T23:18:04+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:18:04 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 18 23:18:04 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 18 23:18:04 volumio volumio[954]: info: Discovery: Getting this device information Jan 18 23:18:04 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:18:04 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:04 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 18 23:18:04 volumio go-librespot[28595]: time="2025-01-18T23:18:04+05:00" level=debug msg="completed keyexchange" Jan 18 23:18:05 volumio go-librespot[28595]: time="2025-01-18T23:18:05+05:00" level=debug msg="completed challenge" Jan 18 23:18:05 volumio go-librespot[28595]: time="2025-01-18T23:18:05+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:18:05 volumio volumio[954]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jan 18 23:18:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:18:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:18:05 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:18:05 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:18:05 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:18:05 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:05 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:05 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:18:05 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:05 volumio volumio[954]: info: [1737224285484] ControllerSpotify::clearAddPlayTrack Jan 18 23:18:05 volumio volumio[954]: info: Sending Spotify command with payload to local API: /player/play Jan 18 23:18:05 volumio volumio[954]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:06 volumio volumio[954]: info: CoreCommandRouter::volumioGetQueue Jan 18 23:18:06 volumio volumio[954]: info: CoreStateMachine::getQueue Jan 18 23:18:06 volumio volumio[954]: info: CorePlayQueue::getQueue Jan 18 23:18:06 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:18:06 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:06 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:18:06 volumio volumio[954]: (node:954) 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: 3492) Jan 18 23:18:06 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:18:06 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:18:06 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:06 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:08 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:08 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:18:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5930. Jan 18 23:18:08 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:18:08 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:18:08 volumio go-librespot[28620]: Librespot-go daemon starting... Jan 18 23:18:08 volumio go-librespot[28620]: time="2025-01-18T23:18:08+05:00" level=info msg="generated new device id: 9c78de2fb902d4bd9066cbdc0722db568572485c" Jan 18 23:18:08 volumio go-librespot[28620]: time="2025-01-18T23:18:08+05:00" level=debug msg="stored credentials not found" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=debug msg="zeroconf server listening on port 41507" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=debug msg="obtained new client token: AACzEAHThtUJj8BH1+37p6JHiZDU0Epfx/Y6IrPE1FH0p3V7G6MRNuxE+C3zWUTyc/SD7Zx7iD6NZsTjCiyy5LPFPmyhA25ImmvE/t9zbJb/ro3gRf5dD9y7IMhFSvfLFrAokkiYd5DCb6Q0CdXeb3njbzGU0BshYk/yqIFxWNKlgnzwoqD95DF7rzOtQ4cel4lIGPERTajmnvz8C9t8PrFQpM6ZVYaNzEGH1VEKuYv5g3Y/32NmAzKRxsawPHg=" Jan 18 23:18:09 volumio go-librespot[28620]: time="2025-01-18T23:18:09+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:18:10 volumio go-librespot[28620]: time="2025-01-18T23:18:10+05:00" level=debug msg="completed keyexchange" Jan 18 23:18:10 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jan 18 23:18:10 volumio volumio[954]: info: Preload queue cleared Jan 18 23:18:10 volumio go-librespot[28620]: time="2025-01-18T23:18:10+05:00" level=debug msg="completed challenge" Jan 18 23:18:10 volumio go-librespot[28620]: time="2025-01-18T23:18:10+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:18:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:18:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:18:11 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:11 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:12 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jan 18 23:18:12 volumio volumio[954]: info: READ Jan 18 23:18:12 volumio volumio[954]: info: Preload queue cleared Jan 18 23:18:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:18:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5931. Jan 18 23:18:14 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:18:14 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:18:14 volumio go-librespot[28683]: Librespot-go daemon starting... Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=info msg="generated new device id: 816f643446379e9a7857e45fbb106d67d6a1651d" Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="stored credentials not found" Jan 18 23:18:14 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Jan 18 23:18:14 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="new websocket client" Jan 18 23:18:14 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 18 23:18:14 volumio go-librespot[28683]: time="2025-01-18T23:18:14+05:00" level=debug msg="zeroconf server listening on port 39561" Jan 18 23:18:15 volumio volumio[954]: info: Preload queue cleared Jan 18 23:18:15 volumio go-librespot[28683]: time="2025-01-18T23:18:15+05:00" level=debug msg="obtained new client token: AABzTZI7pRoNryvATlDRZk6dY6DQnGOU2VprRvh7nhf/pfGSCn8vTyU68D7DXUFL0uH5r8hV7IXh+qs/6dXcDLxMHxtpLwmrXoLi1oZsmuNYg629k7vC9qIAA1w6+nGZSLUdjDB0/JfK5FNpQ1tShZU8YeAGEiY2/hQaVRU1vYd6T8fzQxfm1zpE5IL+A2uD5awayuZjOOEwbPrJb5/lS9h7ZzglOAb8y+ljGKgvvm90zjXDn/nxmDU9wL3K4Kk=" Jan 18 23:18:15 volumio go-librespot[28683]: time="2025-01-18T23:18:15+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:18:15 volumio go-librespot[28683]: time="2025-01-18T23:18:15+05:00" level=debug msg="completed keyexchange" Jan 18 23:18:16 volumio go-librespot[28683]: time="2025-01-18T23:18:16+05:00" level=debug msg="completed challenge" Jan 18 23:18:16 volumio go-librespot[28683]: time="2025-01-18T23:18:16+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:18:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:18:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:18:16 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:18:17 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:18:17 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:17 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:18:17 volumio volumio[954]: (node:954) 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: 3493) Jan 18 23:18:17 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:18:17 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:18:17 volumio volumio[954]: info: CorePlayQueue::getTrack 17 Jan 18 23:18:17 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:18 volumio volumio[954]: info: Preload queue cleared Jan 18 23:18:18 volumio volumio[954]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::ClearQueue Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::stop Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::clearPlayQueue Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::saveQueue Jan 18 23:18:18 volumio volumio[954]: info: CoreCommandRouter::volumioPushQueue Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::addQueueItems Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::addQueueItems Jan 18 23:18:18 volumio volumio[954]: info: Preload queue cleared Jan 18 23:18:18 volumio volumio[954]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=157531 Jan 18 23:18:18 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jan 18 23:18:18 volumio volumio[954]: info: CoreCommandRouter::volumioPushQueue Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::saveQueue Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::updateTrackBlock Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::getTrackBlock Jan 18 23:18:18 volumio volumio[954]: info: CoreCommandRouter::volumioPlay Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::play index 0 Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::stop Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::play index undefined Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:18 volumio volumio[954]: info: CoreStateMachine::startPlaybackTimer Jan 18 23:18:18 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:18 volumio volumio[954]: info: [1737224298047] ControllerWebradio::clearAddPlayTrack Jan 18 23:18:18 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand stop Jan 18 23:18:18 volumio volumio[954]: info: sendMpdCommand stop took 8 milliseconds Jan 18 23:18:18 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand clear Jan 18 23:18:18 volumio volumio[954]: info: sendMpdCommand clear took 1 milliseconds Jan 18 23:18:18 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=157531" Jan 18 23:18:18 volumio volumio[954]: info: Jan 18 23:18:18 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:18 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:18 volumio volumio[954]: info: Jan 18 23:18:18 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:18 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:18 volumio volumio[954]: info: Jan 18 23:18:18 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:18 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:18 volumio volumio[954]: error: Upnp client error: Error: This socket has been ended by the other party Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=157531" took 945 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand play Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 947ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 943ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 943ms Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand play took 10 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 10ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 4ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 3ms Jan 18 23:18:19 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:19 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 9 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 8 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 7 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 5 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 4 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 9 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 12 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 12 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 12 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus stop Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 73ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 86ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 85ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 84ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 84ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 67 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 243/600) Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5932. Jan 18 23:18:19 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 102ms Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:18:19 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:18:19 volumio go-librespot[28699]: Librespot-go daemon starting... Jan 18 23:18:19 volumio go-librespot[28699]: time="2025-01-18T23:18:19+05:00" level=info msg="generated new device id: 29b8deeb24a670fa9fda3c37c4bf9ae859eb2747" Jan 18 23:18:19 volumio go-librespot[28699]: time="2025-01-18T23:18:19+05:00" level=debug msg="stored credentials not found" Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 17ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 13 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 13ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 10 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 10ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 8 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces system playlist update Jan 18 23:18:19 volumio volumio[954]: info: Ignoring MPD Status Update Jan 18 23:18:19 volumio volumio[954]: info: Jan 18 23:18:19 volumio volumio[954]: ---------------------------- MPD announces state update: player Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::getState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand status Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 111ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 107 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 104 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 104 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 103 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 102ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 101 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 100ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand status took 99 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseState Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 179ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 177ms Jan 18 23:18:19 volumio volumio[954]: info: ------------------------------ 174ms Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 76 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 75 milliseconds Jan 18 23:18:19 volumio volumio[954]: info: sendMpdCommand playlistinfo took 74 milliseconds Jan 18 23:18:19 volumio volumio[954]: verbose: ControllerMpd::parseTrackInfo Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:19 volumio volumio[954]: info: ControllerMpd::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::servicePushState Jan 18 23:18:19 volumio volumio[954]: info: CorePlayQueue::getTrack 0 Jan 18 23:18:19 volumio volumio[954]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"Sobotnie Party Mix z Radiem Italo4you!","artist":"Radio Italo4you","album":null,"uri":"http://91.232.4.33:8018/stream","trackType":""} Jan 18 23:18:19 volumio volumio[954]: verbose: CURRENT POSITION 0 Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState stateService play Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::syncState currentStatus play Jan 18 23:18:19 volumio volumio[954]: info: Received an update from plugin. extracting info from payload Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 18 23:18:19 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:19 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:20 volumio volumio[954]: info: CoreStateMachine::pushState Jan 18 23:18:20 volumio volumio[954]: info: CoreCommandRouter::volumioPushState Jan 18 23:18:20 volumio volumio[954]: info: ------------------------------ 248ms Jan 18 23:18:20 volumio volumio[954]: info: ------------------------------ 239ms Jan 18 23:18:20 volumio volumio[954]: info: ------------------------------ 238ms Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:20 volumio go-librespot[28699]: time="2025-01-18T23:18:20+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 18 23:18:20 volumio go-librespot[28699]: time="2025-01-18T23:18:20+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 18 23:18:20 volumio go-librespot[28699]: time="2025-01-18T23:18:20+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 18 23:18:20 volumio go-librespot[28699]: time="2025-01-18T23:18:20+05:00" level=debug msg="zeroconf server listening on port 36605" Jan 18 23:18:20 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 18 23:18:21 volumio go-librespot[28699]: time="2025-01-18T23:18:21+05:00" level=debug msg="obtained new client token: AAAe+AHCpmW+fWlo7aIxgmSMLupvkR5DIxGwCjTicrw8AsbCFUXd52Ji6MXpvGbRo2XdFR9j7KLwS1vml+voLg8BMQl4AICBLdHSVxz3rMRB8lID2ZANZ8ByZGjrFPpWG+XEZwp1OZL3kvpJXdAbBaBkYye7v7umYMIzRtu0WFslLoMt8WTyWsGRc6bb2UzBW3Tr9kFm26+aj2g9/Qp6Tzb6lzJGZ1pVr7x3ASIhahOeUgIu6vH51D8HtdA0mrU=" Jan 18 23:18:21 volumio go-librespot[28699]: time="2025-01-18T23:18:21+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:18:22 volumio go-librespot[28699]: time="2025-01-18T23:18:22+05:00" level=debug msg="completed keyexchange" Jan 18 23:18:22 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:22 volumio go-librespot[28699]: time="2025-01-18T23:18:22+05:00" level=debug msg="new websocket client" Jan 18 23:18:22 volumio volumio[954]: info: Connection to go-librespot Websocket established Jan 18 23:18:22 volumio go-librespot[28699]: time="2025-01-18T23:18:22+05:00" level=debug msg="completed challenge" Jan 18 23:18:22 volumio go-librespot[28699]: time="2025-01-18T23:18:22+05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jan 18 23:18:22 volumio volumio[954]: info: Connection to go-librespot Websocket closed Jan 18 23:18:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 18 23:18:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 18 23:18:25 volumio volumio[954]: info: Getting Spotify volume Jan 18 23:18:25 volumio volumio[954]: (node:954) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:25 volumio volumio[954]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 18 23:18:25 volumio volumio[954]: (node:954) 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: 3494) Jan 18 23:18:25 volumio volumio[954]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 18 23:18:25 volumio volumio[954]: info: CoreCommandRouter::volumioGetState Jan 18 23:18:25 volumio volumio[954]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 18 23:18:25 volumio volumio[954]: info: Initializing connection to go-librespot Websocket Jan 18 23:18:25 volumio volumio[954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 18 23:18:25 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 18 23:18:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5933. Jan 18 23:18:25 volumio systemd[1]: Stopped go-librespot Daemon. Jan 18 23:18:25 volumio systemd[1]: Started go-librespot Daemon. Jan 18 23:18:25 volumio go-librespot[28742]: Librespot-go daemon starting... Jan 18 23:18:25 volumio go-librespot[28742]: time="2025-01-18T23:18:25+05:00" level=info msg="generated new device id: 353288b9b180e564b9502938fc1619cfe3ec917b" Jan 18 23:18:25 volumio go-librespot[28742]: time="2025-01-18T23:18:25+05:00" level=debug msg="stored credentials not found" Jan 18 23:18:26 volumio go-librespot[28742]: time="2025-01-18T23:18:26+05:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 18 23:18:26 volumio go-librespot[28742]: time="2025-01-18T23:18:26+05:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 18 23:18:26 volumio go-librespot[28742]: time="2025-01-18T23:18:26+05:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 18 23:18:26 volumio go-librespot[28742]: time="2025-01-18T23:18:26+05:00" level=debug msg="zeroconf server listening on port 38911" Jan 18 23:18:26 volumio volumio[954]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 18 23:18:26 volumio volumio[954]: Error: read ECONNRESET Jan 18 23:18:26 volumio volumio[954]: at TCP.onStreamRead (internal/stream_base_commons.js:209:20) { Jan 18 23:18:26 volumio volumio[954]: errno: -104, Jan 18 23:18:26 volumio volumio[954]: code: 'ECONNRESET', Jan 18 23:18:26 volumio volumio[954]: syscall: 'read' Jan 18 23:18:26 volumio volumio[954]: } Jan 18 23:18:26 volumio volumio[954]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 18 23:18:26 volumio kernel: hwmon hwmon1: Voltage normalised Jan 18 23:18:27 volumio go-librespot[28742]: time="2025-01-18T23:18:27+05:00" level=debug msg="obtained new client token: AADeC3a47TL0HFN/sTtZ/PeXV298h6aAqzRikmTRgsaj6RhRQcr41Y3Du4TNN+TGyUJyyXqsSYdtxnyLjtlh/eyYuDCR0XMrysB9Ot/0v4rxet1wk1NmFTfHwkz3n3cZcZGuJ1dLWTbTELRIYmPKrOs3mzVhsR7Dhr8xqFPDY7mPVhAzXOgXss/w6cuqvUP3tCQ3gFdDTSj02ofJURlHFsu3RTB8EpYzBrbISydA8nb0g1scyKqf/y1X9DwpjwU=" Jan 18 23:18:27 volumio go-librespot[28742]: time="2025-01-18T23:18:27+05:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 18 23:18:27 volumio sudo[28762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-18 23:17 Jan 18 23:18:27 volumio sudo[28762]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 18 23:18:27 volumio go-librespot[28742]: time="2025-01-18T23:18:27+05:00" level=debug msg="completed keyexchange" 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"