-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Fri 2024-05-10 18:11:14 CST. -- May 10 18:10:14 volumio go-librespot[3848]: time="2024-05-10T18:10:14+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 10 18:10:14 volumio go-librespot[3848]: time="2024-05-10T18:10:14+08:00" level=debug msg="completed keyexchange" May 10 18:10:15 volumio volumio[874]: info: peppy_screensaver: Start PeppyMeter May 10 18:10:15 volumio go-librespot[3848]: time="2024-05-10T18:10:15+08:00" level=debug msg="completed challenge" May 10 18:10:15 volumio go-librespot[3848]: time="2024-05-10T18:10:15+08: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" May 10 18:10:15 volumio volumio[874]: (node:874) UnhandledPromiseRejectionWarning: Error: socket hang up May 10 18:10:15 volumio volumio[874]: at connResetException (internal/errors.js:607:14) May 10 18:10:15 volumio volumio[874]: at Socket.socketOnEnd (_http_client.js:493:23) May 10 18:10:15 volumio volumio[874]: at Socket.emit (events.js:327:22) May 10 18:10:15 volumio volumio[874]: at endReadableNT (internal/streams/readable.js:1327:12) May 10 18:10:15 volumio volumio[874]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 10 18:10:15 volumio volumio[874]: (node:874) 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: 54) May 10 18:10:15 volumio volumio[874]: info: Connection to go-librespot Websocket closed May 10 18:10:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 10 18:10:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 10 18:10:18 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:10:18 volumio volumio[874]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 10 18:10:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 10 18:10:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. May 10 18:10:18 volumio systemd[1]: Stopped go-librespot Daemon. May 10 18:10:18 volumio systemd[1]: Started go-librespot Daemon. May 10 18:10:18 volumio go-librespot[3911]: Librespot-go daemon starting... May 10 18:10:18 volumio go-librespot[3911]: time="2024-05-10T18:10:18+08:00" level=info msg="generated new device id: 3de142a26c6d7bf7c0bb53bd771f358fcb1ab9ca" May 10 18:10:18 volumio go-librespot[3911]: time="2024-05-10T18:10:18+08:00" level=debug msg="stored credentials not found" May 10 18:10:20 volumio go-librespot[3911]: time="2024-05-10T18:10:20+08:00" level=debug msg="obtained new client token: AACd35gbr6ke3Za71B5J4X4Pe3pQuk69gluTrVUhUtsT2fQGdzb4t5cMl7622jFS6xxnhSsiFcgg0RUbdSnco4ThOWOF8SYDnhwcos6LcMIZTw5S9boX4XQYK2NXbnOKIn2hjIplNVOllSr5j/tSyGT5VJi9GLTtT/Imh8jJFPVLJaZQTPG3ZmRcj5k9H4HuBtS6Fcs+CBTRez/XGiks/kH1JpX94L7g2EYsTf+sQYpdOf4sO1ufOoViyIfMIRM=" May 10 18:10:21 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:10:21 volumio go-librespot[3911]: time="2024-05-10T18:10:21+08:00" level=debug msg="new websocket client" May 10 18:10:21 volumio volumio[874]: info: Connection to go-librespot Websocket established May 10 18:10:21 volumio go-librespot[3911]: time="2024-05-10T18:10:21+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 10 18:10:24 volumio volumio[874]: info: Getting Spotify volume May 10 18:10:24 volumio volumio[874]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 May 10 18:10:24 volumio volumio[874]: info: CoreCommandRouter::volumioGetState May 10 18:10:24 volumio volumio[874]: info: CorePlayQueue::getTrack 9 May 10 18:10:24 volumio volumio[874]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 May 10 18:10:26 volumio go-librespot[3911]: time="2024-05-10T18:10:26+08:00" level=debug msg="completed keyexchange" May 10 18:10:26 volumio volumio[874]: info: CoreCommandRouter::volumioRandom May 10 18:10:26 volumio volumio[874]: info: CoreCommandRouter::writePlayerControls May 10 18:10:26 volumio volumio[874]: info: CorePlayQueue::getTrack 9 May 10 18:10:26 volumio volumio[874]: info: CoreStateMachine::setRepeat true single true May 10 18:10:26 volumio volumio[874]: info: CoreStateMachine::pushState May 10 18:10:26 volumio volumio[874]: info: CorePlayQueue::getTrack 9 May 10 18:10:26 volumio volumio[874]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 18:10:26 volumio volumio[874]: info: CoreCommandRouter::volumioPushState May 10 18:10:26 volumio volumio[874]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 May 10 18:10:27 volumio go-librespot[3911]: time="2024-05-10T18:10:27+08:00" level=debug msg="completed challenge" May 10 18:10:27 volumio go-librespot[3911]: time="2024-05-10T18:10:27+08: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" May 10 18:10:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 10 18:10:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 10 18:10:27 volumio volumio[874]: (node:874) UnhandledPromiseRejectionWarning: Error: socket hang up May 10 18:10:27 volumio volumio[874]: at connResetException (internal/errors.js:607:14) May 10 18:10:27 volumio volumio[874]: at Socket.socketOnEnd (_http_client.js:493:23) May 10 18:10:27 volumio volumio[874]: at Socket.emit (events.js:327:22) May 10 18:10:27 volumio volumio[874]: at endReadableNT (internal/streams/readable.js:1327:12) May 10 18:10:27 volumio volumio[874]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 10 18:10:27 volumio volumio[874]: (node:874) 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: 55) May 10 18:10:27 volumio volumio[874]: info: Connection to go-librespot Websocket closed May 10 18:10:29 volumio volumio[874]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 May 10 18:10:29 volumio volumio[874]: info: touch_display: Setting screensaver timeout to 15 seconds. May 10 18:10:30 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:10:30 volumio volumio[874]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 10 18:10:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 10 18:10:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. May 10 18:10:30 volumio systemd[1]: Stopped go-librespot Daemon. May 10 18:10:30 volumio systemd[1]: Started go-librespot Daemon. May 10 18:10:30 volumio go-librespot[3973]: Librespot-go daemon starting... May 10 18:10:30 volumio go-librespot[3973]: time="2024-05-10T18:10:30+08:00" level=info msg="generated new device id: 4765fa14109f2d224aae1f3e58352f367c6aea0e" May 10 18:10:30 volumio go-librespot[3973]: time="2024-05-10T18:10:30+08:00" level=debug msg="stored credentials not found" May 10 18:10:31 volumio volumio[874]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 8 May 10 18:10:31 volumio volumio[874]: info: CoreCommandRouter::volumioGetState May 10 18:10:31 volumio volumio[874]: info: CorePlayQueue::getTrack 9 May 10 18:10:31 volumio volumio[874]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/Joe%20Cocker/619f3aec-49db-4466-8ab0-c809cc974f1d.jpg' May 10 18:10:32 volumio go-librespot[3973]: time="2024-05-10T18:10:32+08:00" level=debug msg="obtained new client token: AADQv1d0drsqu+mw5d9y+8fI7nRUTjBtyc9DLeURDILWmL+h5Gblibv309irzCLNEogwvTbiWoLlz99gHZ7cLeaEm8Q0MinUMOOUiuh6NBnPMcC6mrepsxcmM1Uo+f4toDNEvWP96KDi4f4jF5ekOpeOdA+V2UkdI1zvLHOkMh4ZwRg9lwgTpkjUuOCJ+mdmOTsTpRa9Hys8+zB1eFBspeutdJRNCA6jgVlN8EqeQvKu6/sY6oktTVuti72dmHw=" May 10 18:10:33 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:10:33 volumio go-librespot[3973]: time="2024-05-10T18:10:33+08:00" level=debug msg="new websocket client" May 10 18:10:33 volumio volumio[874]: info: Connection to go-librespot Websocket established May 10 18:10:34 volumio go-librespot[3973]: time="2024-05-10T18:10:34+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 10 18:10:36 volumio volumio[874]: info: Getting Spotify volume May 10 18:10:36 volumio volumio[874]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 10 18:10:36 volumio volumio[874]: info: CoreCommandRouter::volumioGetState May 10 18:10:36 volumio volumio[874]: info: CorePlayQueue::getTrack 9 May 10 18:10:36 volumio volumio[874]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 May 10 18:10:55 volumio volumio[874]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Could not access weather service: missing geographic coordinates. May 10 18:10:55 volumio volumio[874]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:106:19) May 10 18:10:55 volumio volumio[874]: at Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:113:37) May 10 18:10:55 volumio volumio[874]: at /data/plugins/user_interface/now_playing/dist/app/Router.js:47:13 May 10 18:10:55 volumio volumio[874]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 10 18:10:55 volumio volumio[874]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:144:13) May 10 18:10:55 volumio volumio[874]: at Route.dispatch (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:114:3) May 10 18:10:55 volumio volumio[874]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 10 18:10:55 volumio volumio[874]: at /data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:284:15 May 10 18:10:55 volumio volumio[874]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:365:14) May 10 18:10:55 volumio volumio[874]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:376:14) May 10 18:10:55 volumio volumio[874]: at Function.process_params (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:421:3) May 10 18:10:55 volumio volumio[874]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:280:10) May 10 18:10:55 volumio volumio[874]: at Function.handle (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:175:3) May 10 18:10:55 volumio volumio[874]: at router (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:47:12) May 10 18:10:55 volumio volumio[874]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) May 10 18:11:07 volumio go-librespot[3973]: time="2024-05-10T18:11:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp: lookup ap-gae2.spotify.com: device or resource busy" May 10 18:11:07 volumio volumio[874]: (node:874) UnhandledPromiseRejectionWarning: Error: socket hang up May 10 18:11:07 volumio volumio[874]: at connResetException (internal/errors.js:607:14) May 10 18:11:07 volumio volumio[874]: at Socket.socketOnEnd (_http_client.js:493:23) May 10 18:11:07 volumio volumio[874]: at Socket.emit (events.js:327:22) May 10 18:11:07 volumio volumio[874]: at endReadableNT (internal/streams/readable.js:1327:12) May 10 18:11:07 volumio volumio[874]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 10 18:11:07 volumio volumio[874]: (node:874) 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: 57) May 10 18:11:07 volumio volumio[874]: info: Connection to go-librespot Websocket closed May 10 18:11:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 10 18:11:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 10 18:11:10 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:11:10 volumio volumio[874]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 10 18:11:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 10 18:11:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. May 10 18:11:10 volumio systemd[1]: Stopped go-librespot Daemon. May 10 18:11:10 volumio systemd[1]: Started go-librespot Daemon. May 10 18:11:10 volumio go-librespot[4116]: Librespot-go daemon starting... May 10 18:11:10 volumio go-librespot[4116]: time="2024-05-10T18:11:10+08:00" level=info msg="generated new device id: ca054b7a83507208452d6d2b17981899f18867e0" May 10 18:11:10 volumio go-librespot[4116]: time="2024-05-10T18:11:10+08:00" level=debug msg="stored credentials not found" May 10 18:11:13 volumio volumio[874]: info: Initializing connection to go-librespot Websocket May 10 18:11:13 volumio volumio[874]: info: Connection to go-librespot Websocket established May 10 18:11:13 volumio go-librespot[4116]: time="2024-05-10T18:11:13+08:00" level=debug msg="new websocket client" May 10 18:11:14 volumio volumio[874]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 18:11:14 volumio volumio[874]: Error: connect ETIMEDOUT 157.240.8.41:80 May 10 18:11:14 volumio volumio[874]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { May 10 18:11:14 volumio volumio[874]: errno: -110, May 10 18:11:14 volumio volumio[874]: code: 'ETIMEDOUT', May 10 18:11:14 volumio volumio[874]: syscall: 'connect', May 10 18:11:14 volumio volumio[874]: address: '157.240.8.41', May 10 18:11:14 volumio volumio[874]: port: 80 May 10 18:11:14 volumio volumio[874]: } May 10 18:11:14 volumio volumio[874]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 18:11:14 volumio sudo[4141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-10 18:10 May 10 18:11:14 volumio sudo[4141]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"