-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Thu 2022-03-31 12:59:15 UTC. -- Mar 31 12:58:11 volumio volumio[789]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io Mar 31 12:58:12 volumio volumio[789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Mar 31 12:58:13 volumio go-librespot[972]: time="2022-03-31T12:58:13Z" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 31 12:58:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 31 12:58:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 31 12:58:13 volumio volumio[789]: error: MyVolumio Plugin failed to start in a timely fashion Mar 31 12:58:13 volumio volumio[789]: info: BOOT COMPLETED Mar 31 12:58:13 volumio volumio[789]: [Metrics] CommandRouter: 42s 201.30ms Mar 31 12:58:13 volumio volumio[789]: info: CoreCommandRouter::volumiosetStartupVolume Mar 31 12:58:13 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 31 12:58:13 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 31 12:58:13 volumio volumio[789]: info: CoreCommandRouter::Close All Modals sent Mar 31 12:58:13 volumio volumio[789]: info: CoreCommandRouter::Close All Modals sent Mar 31 12:58:14 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 31 12:58:14 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 31 12:58:14 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 31 12:58:16 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 31 12:58:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 31 12:58:16 volumio systemd[1]: Stopped go-librespot Daemon. Mar 31 12:58:16 volumio systemd[1]: Started go-librespot Daemon. Mar 31 12:58:16 volumio go-librespot[1011]: go-librespot daemon starting... Mar 31 12:58:16 volumio go-librespot[1011]: time="2022-03-31T12:58:16Z" level=info msg="running go-librespot 0.2.0" Mar 31 12:58:16 volumio go-librespot[1011]: time="2022-03-31T12:58:16Z" level=debug msg="app state loaded" Mar 31 12:58:17 volumio go-librespot[1011]: time="2022-03-31T12:58:17Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 31 12:58:21 volumio volumio[918]: .....................................................................................++++ Mar 31 12:58:21 volumio volumio[789]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.251&uuid=42a9fd0fbf6e5724d336b8f74235ff98" http://updates.volumio.org/downloader-v1/track-device Mar 31 12:58:21 volumio volumio[789]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 31 12:58:21 volumio volumio[789]: Dload Upload Total Spent Left Speed Mar 31 12:58:21 volumio volumio[789]: [1.5K blob data] Mar 31 12:58:21 volumio volumio[789]: retrying in 5 seconds, trial 0 Mar 31 12:58:21 volumio volumio[789]: info: Volumio Calling Home Mar 31 12:58:23 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 31 12:58:23 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 31 12:58:27 volumio volumio[789]: info: Discovery: adding 501916a1-6ca4-4bf6-8ca5-27709ff402b2 Mar 31 12:58:27 volumio volumio[789]: info: mDNS: Found device Volumio Mar 31 12:58:27 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:58:27 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:29 volumio ntpd[643]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Mar 31 12:58:30 volumio go-librespot[1011]: time="2022-03-31T12:58:30Z" level=debug msg="new websocket client" Mar 31 12:58:30 volumio volumio[789]: info: Connection to go-librespot Websocket established Mar 31 12:58:33 volumio volumio[789]: info: Getting Spotify volume Mar 31 12:58:35 volumio go-librespot[1011]: time="2022-03-31T12:58:35Z" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 31 12:58:35 volumio volumio[789]: (node:789) UnhandledPromiseRejectionWarning: Error: socket hang up Mar 31 12:58:35 volumio volumio[789]: at connResetException (internal/errors.js:607:14) Mar 31 12:58:35 volumio volumio[789]: at Socket.socketOnEnd (_http_client.js:493:23) Mar 31 12:58:35 volumio volumio[789]: at Socket.emit (events.js:327:22) Mar 31 12:58:35 volumio volumio[789]: at endReadableNT (internal/streams/readable.js:1327:12) Mar 31 12:58:35 volumio volumio[789]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Mar 31 12:58:35 volumio volumio[789]: (Use `node --trace-warnings ...` to show where the warning was created) Mar 31 12:58:35 volumio volumio[789]: (node:789) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2) Mar 31 12:58:35 volumio volumio[789]: (node:789) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Mar 31 12:58:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 31 12:58:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 31 12:58:35 volumio volumio[789]: info: Connection to go-librespot Websocket closed Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 31 12:58:36 volumio volumio[789]: info: Discovery: Getting this device information Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:58:36 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 31 12:58:36 volumio volumio[789]: verbose: New Socket.io Connection to 192.168.1.61:3000 from 192.168.1.71 UA: Dart/3.5 (dart:io) Total Clients: 3 Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:58:36 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 31 12:58:36 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 31 12:58:37 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:58:37 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:38 volumio sudo[1025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 31 12:58:38 volumio sudo[1025]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 31 12:58:38 volumio sudo[1025]: pam_unix(sudo:session): session closed for user root Mar 31 12:58:38 volumio sudo[1027]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 31 12:58:38 volumio sudo[1027]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 31 12:58:38 volumio sudo[1027]: pam_unix(sudo:session): session closed for user root Mar 31 12:58:38 volumio volumio[789]: verbose: New Socket.io Connection to 192.168.1.61 from 192.168.1.71 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 4 Mar 31 12:58:38 volumio sudo[1031]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 31 12:58:38 volumio sudo[1031]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 31 12:58:38 volumio sudo[1031]: pam_unix(sudo:session): session closed for user root Mar 31 12:58:38 volumio sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 31 12:58:38 volumio sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 31 12:58:38 volumio sudo[1033]: pam_unix(sudo:session): session closed for user root Mar 31 12:58:38 volumio volumio[789]: verbose: New Socket.io Connection to 192.168.1.61 from 192.168.1.71 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 4 Mar 31 12:58:38 volumio volumio[789]: info: Initializing connection to go-librespot Websocket Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:58:39 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 31 12:58:39 volumio volumio[789]: info: Listing playlists Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 31 12:58:39 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 31 12:58:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 31 12:58:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 31 12:58:39 volumio systemd[1]: Stopped go-librespot Daemon. Mar 31 12:58:39 volumio systemd[1]: Started go-librespot Daemon. Mar 31 12:58:39 volumio go-librespot[1040]: go-librespot daemon starting... Mar 31 12:58:39 volumio go-librespot[1040]: time="2022-03-31T12:58:39Z" level=info msg="running go-librespot 0.2.0" Mar 31 12:58:39 volumio go-librespot[1040]: time="2022-03-31T12:58:39Z" level=debug msg="app state loaded" Mar 31 12:58:40 volumio volumio[789]: info: CoreCommandRouter::volumioGetVisibleSources Mar 31 12:58:40 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 31 12:58:40 volumio volumio[789]: info: CoreCommandRouter::volumioGetQueue Mar 31 12:58:40 volumio volumio[789]: info: CoreStateMachine::getQueue Mar 31 12:58:40 volumio volumio[789]: info: CorePlayQueue::getQueue Mar 31 12:58:40 volumio go-librespot[1040]: time="2022-03-31T12:58:40Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 31 12:58:41 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 31 12:58:41 volumio volumio[789]: info: CURURI: artists:// Mar 31 12:58:44 volumio volumio[918]: ......................................................................................++++ Mar 31 12:58:44 volumio volumio[918]: e is 65537 (0x010001) Mar 31 12:58:44 volumio volumio[918]: writing RSA key Mar 31 12:58:48 volumio ntpd[643]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Mar 31 12:58:49 volumio volumio[789]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.251&uuid=42a9fd0fbf6e5724d336b8f74235ff98" http://updates.volumio.org/downloader-v1/track-device Mar 31 12:58:49 volumio volumio[789]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 31 12:58:49 volumio volumio[789]: Dload Upload Total Spent Left Speed Mar 31 12:58:49 volumio volumio[789]: [1.5K blob data] Mar 31 12:58:49 volumio volumio[789]: retrying in 5 seconds, trial 1 Mar 31 12:58:49 volumio volumio[789]: info: Volumio Calling Home Mar 31 12:58:50 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 31 12:58:50 volumio volumio[789]: info: CURURI: artists://Brigitte Mar 31 12:58:52 volumio volumio[789]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::ClearQueue Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::stop Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 12:58:52 volumio volumio[789]: verbose: UNSET VOLATILE Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::clearPlayQueue Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::saveQueue Mar 31 12:58:52 volumio volumio[789]: info: CoreCommandRouter::volumioPushState Mar 31 12:58:52 volumio volumio[789]: info: CoreCommandRouter::volumioPushQueue Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::addQueueItems Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::addQueueItems Mar 31 12:58:52 volumio volumio[789]: info: Adding Item to queue: artists://Brigitte Mar 31 12:58:52 volumio volumio[789]: info: Exploding uri artists://Brigitte in service mpd Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::saveQueue Mar 31 12:58:52 volumio volumio[789]: info: CoreCommandRouter::volumioPushQueue Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::updateTrackBlock Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::getTrackBlock Mar 31 12:58:52 volumio volumio[789]: info: CoreCommandRouter::volumioPlay Mar 31 12:58:52 volumio volumio[789]: verbose: UNSET VOLATILE Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::play index 0 Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::stop Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 12:58:52 volumio volumio[789]: verbose: UNSET VOLATILE Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::play index undefined Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:52 volumio volumio[789]: info: CoreStateMachine::startPlaybackTimer Mar 31 12:58:52 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:52 volumio volumio[789]: verbose: ControllerMpd::clearAddPlayTracks USB/62E3-A448/BRIGITTE/Et vous, tu m'aimes /01 Battez-vous-.mp3 Mar 31 12:58:52 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand stop Mar 31 12:58:52 volumio volumio[789]: info: sendMpdCommand stop took 7 milliseconds Mar 31 12:58:52 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand clear Mar 31 12:58:52 volumio volumio[789]: info: Mar 31 12:58:52 volumio volumio[789]: ---------------------------- MPD announces system playlist update Mar 31 12:58:52 volumio volumio[789]: info: Ignoring MPD Status Update Mar 31 12:58:52 volumio volumio[789]: info: sendMpdCommand clear took 25 milliseconds Mar 31 12:58:52 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand add "USB/62E3-A448/BRIGITTE/Et vous, tu m'aimes /01 Battez-vous-.mp3" Mar 31 12:58:52 volumio volumio[789]: error: updateQueue error: null Mar 31 12:58:52 volumio volumio[789]: info: Mar 31 12:58:52 volumio volumio[789]: ---------------------------- MPD announces system playlist update Mar 31 12:58:52 volumio volumio[789]: info: Ignoring MPD Status Update Mar 31 12:58:52 volumio volumio[789]: info: ------------------------------ 24ms Mar 31 12:58:52 volumio volumio[789]: info: sendMpdCommand add "USB/62E3-A448/BRIGITTE/Et vous, tu m'aimes /01 Battez-vous-.mp3" took 29 milliseconds Mar 31 12:58:52 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand play Mar 31 12:58:53 volumio volumio[789]: info: ------------------------------ 28ms Mar 31 12:58:53 volumio volumio[789]: info: sendMpdCommand play took 28 milliseconds Mar 31 12:58:53 volumio volumio[789]: info: Mar 31 12:58:53 volumio volumio[789]: ---------------------------- MPD announces state update: player Mar 31 12:58:53 volumio volumio[789]: info: ControllerMpd::getState Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand status Mar 31 12:58:53 volumio volumio[789]: info: Mar 31 12:58:53 volumio volumio[789]: ---------------------------- MPD announces state update: player Mar 31 12:58:53 volumio volumio[789]: info: ControllerMpd::getState Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand status Mar 31 12:58:53 volumio volumio[789]: info: sendMpdCommand status took 14 milliseconds Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::parseState Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 12:58:53 volumio volumio[789]: info: sendMpdCommand status took 22 milliseconds Mar 31 12:58:53 volumio volumio[789]: info: sendMpdCommand playlistinfo took 6 milliseconds Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::parseState Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::parseTrackInfo Mar 31 12:58:53 volumio volumio[789]: info: ControllerMpd::pushState Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::servicePushState Mar 31 12:58:53 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:53 volumio volumio[789]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":243,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Battez-Vous","artist":"Brigitte","album":"Et Vous, Tu M'Aimes ?","uri":"USB/62E3-A448/BRIGITTE/Et vous, tu m'aimes /01 Battez-vous-.mp3","trackType":"mp3"} Mar 31 12:58:53 volumio volumio[789]: verbose: CURRENT POSITION 0 Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::syncState stateService play Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::syncState currentStatus stop Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::pushState Mar 31 12:58:53 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::volumioPushState Mar 31 12:58:53 volumio volumio[789]: info: ------------------------------ 79ms Mar 31 12:58:53 volumio volumio[789]: info: sendMpdCommand playlistinfo took 47 milliseconds Mar 31 12:58:53 volumio volumio[789]: verbose: ControllerMpd::parseTrackInfo Mar 31 12:58:53 volumio volumio[789]: info: ControllerMpd::pushState Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::servicePushState Mar 31 12:58:53 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:53 volumio volumio[789]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":243,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Battez-Vous","artist":"Brigitte","album":"Et Vous, Tu M'Aimes ?","uri":"USB/62E3-A448/BRIGITTE/Et vous, tu m'aimes /01 Battez-vous-.mp3","trackType":"mp3"} Mar 31 12:58:53 volumio volumio[789]: verbose: CURRENT POSITION 0 Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::syncState stateService play Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::syncState currentStatus play Mar 31 12:58:53 volumio volumio[789]: info: Received an update from plugin. extracting info from payload Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::pushState Mar 31 12:58:53 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::volumioPushState Mar 31 12:58:53 volumio volumio[789]: info: CoreStateMachine::pushState Mar 31 12:58:53 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:53 volumio volumio[789]: info: CoreCommandRouter::volumioPushState Mar 31 12:58:53 volumio volumio[789]: info: ------------------------------ 118ms Mar 31 12:58:58 volumio volumio[789]: info: VolumeController::SetAlsaVolume85 Mar 31 12:58:58 volumio volumio[789]: info: CoreStateMachine::pushState Mar 31 12:58:58 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:58:58 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 12:58:58 volumio volumio[789]: info: CoreCommandRouter::volumioPushState Mar 31 12:58:58 volumio go-librespot[1040]: time="2022-03-31T12:58:58Z" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 31 12:58:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 31 12:58:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 31 12:59:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 31 12:59:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 31 12:59:01 volumio systemd[1]: Stopped go-librespot Daemon. Mar 31 12:59:01 volumio systemd[1]: Started go-librespot Daemon. Mar 31 12:59:01 volumio go-librespot[1092]: go-librespot daemon starting... Mar 31 12:59:01 volumio go-librespot[1092]: time="2022-03-31T12:59:01Z" level=info msg="running go-librespot 0.2.0" Mar 31 12:59:01 volumio go-librespot[1092]: time="2022-03-31T12:59:01Z" level=debug msg="app state loaded" Mar 31 12:59:02 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 31 12:59:02 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 31 12:59:02 volumio volumio[789]: info: Discovery: Getting this device information Mar 31 12:59:02 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:59:02 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:59:02 volumio volumio[789]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 31 12:59:02 volumio go-librespot[1092]: time="2022-03-31T12:59:02Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 31 12:59:06 volumio ntpd[643]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Mar 31 12:59:13 volumio go-librespot[1092]: time="2022-03-31T12:59:13Z" level=debug msg="new websocket client" Mar 31 12:59:13 volumio volumio[789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Mar 31 12:59:13 volumio volumio[789]: info: Connection to go-librespot Websocket established Mar 31 12:59:13 volumio volumio[789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Mar 31 12:59:13 volumio go-librespot[1092]: time="2022-03-31T12:59:13Z" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": tls: failed to verify certificate: x509: certificate has expired or is not yet valid: current time 2022-03-31T12:59:13Z is before 2025-01-06T00:00:00Z" Mar 31 12:59:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 31 12:59:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 31 12:59:13 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:59:13 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:59:13 volumio volumio[789]: info: Connection to go-librespot Websocket closed Mar 31 12:59:13 volumio volumio[789]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Mar 31 12:59:13 volumio volumio[789]: SPOTIFY: SPOTIFY VOLUME undefined Mar 31 12:59:13 volumio volumio[789]: SPOTIFY: VOLUMIO VOLUME 85 Mar 31 12:59:13 volumio volumio[789]: info: Aligning Spotify Volume to Volumio Volume Mar 31 12:59:13 volumio volumio[789]: info: CoreCommandRouter::volumioGetState Mar 31 12:59:13 volumio volumio[789]: info: CorePlayQueue::getTrack 0 Mar 31 12:59:13 volumio volumio[789]: info: Setting Spotify Volume from Volumio: 85 Mar 31 12:59:14 volumio volumio[789]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 12:59:14 volumio volumio[789]: Error: certificate is not yet valid Mar 31 12:59:14 volumio volumio[789]: at TLSSocket.onConnectSecure (_tls_wrap.js:1497:34) Mar 31 12:59:14 volumio volumio[789]: at TLSSocket.emit (events.js:315:20) Mar 31 12:59:14 volumio volumio[789]: at TLSSocket._finishInit (_tls_wrap.js:932:8) Mar 31 12:59:14 volumio volumio[789]: at TLSWrap.ssl.onhandshakedone (_tls_wrap.js:706:12) { Mar 31 12:59:14 volumio volumio[789]: code: 'CERT_NOT_YET_VALID' Mar 31 12:59:14 volumio volumio[789]: } Mar 31 12:59:14 volumio volumio[789]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 12:59:15 volumio ntpd[643]: Soliciting pool server 162.159.200.1 Mar 31 12:59:15 volumio sudo[1133]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2022-03-31 12:58 Mar 31 12:59:15 volumio sudo[1133]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="1c5fa5a8788b087ca429be9d10851b25c5cc4f5b" VOLUMIO_FE_VERSION="e5ce74e254a237ac98580c4437c4ed223c7d5cd9" VOLUMIO_FE3_VERSION="a86adf3c7ed2d6c50d9bca768f58ab2f56832dc1" VOLUMIO_BE_VERSION="c8882d89d3d4e0a1571e0dc9701741128f5a1656" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 31 Mar 2022 02:51:41 PM CEST" VOLUMIO_VERSION="3.251" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e83cc5fcd68eb3ee4105ab0b8b3779ea"