-- Logs begin at Mon 2024-09-02 17:57:51 BST, end at Mon 2024-09-02 18:07:47 BST. -- Sep 02 18:06:02 volumio go-librespot[1669]: time="2024-09-02T18:06:02+01:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:06:14 volumio go-librespot[1669]: time="2024-09-02T18:06:14+01:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:06:25 volumio go-librespot[1669]: time="2024-09-02T18:06:25+01:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:06:37 volumio go-librespot[1669]: time="2024-09-02T18:06:37+01:00" level=debug msg="fetched chunk 10/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:07 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 02 18:07:11 volumio kernel: hwmon hwmon1: Voltage normalised Sep 02 18:07:18 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 02 18:07:24 volumio kernel: hwmon hwmon1: Voltage normalised Sep 02 18:07:26 volumio go-librespot[1669]: time="2024-09-02T18:07:26+01:00" level=error msg="did not receive last pong from dealer, 60s passed" Sep 02 18:07:29 volumio go-librespot[1669]: time="2024-09-02T18:07:29+01:00" level=debug msg="prefetching next track" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:31 volumio go-librespot[1669]: time="2024-09-02T18:07:31+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Sep 02 18:07:40 volumio go-librespot[1669]: time="2024-09-02T18:07:40+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Sep 02 18:07:40 volumio go-librespot[1669]: time="2024-09-02T18:07:40+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1756" Sep 02 18:07:42 volumio go-librespot[1669]: time="2024-09-02T18:07:42+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 341" Sep 02 18:07:42 volumio go-librespot[1669]: time="2024-09-02T18:07:42+01:00" level=debug msg="fetched chunk 13/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:42 volumio go-librespot[1669]: time="2024-09-02T18:07:42+01:00" level=debug msg="fetched chunk 12/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="selected format OGG_VORBIS_320 (a7e2953af981f2bbc23a018d8372ac2c8b034f36)" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="requested aes key for file a7e2953af981f2bbc23a018d8372ac2c8b034f36, gid: 7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="fetched first chunk of 18, total size is 9419608 bytes" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:43 volumio go-librespot[1669]: time="2024-09-02T18:07:43+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=debug msg="re-established dealer connection" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=debug msg="received connection id: NzA3MWRlMTEtNzJlYi00OTM3LTk0ZGMtZjEzNmU5MmUyMWRkK2RlYWxlcit0Y3A6Ly8wYWNhNTgwNy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArREFDMTJBQ0U3NEEwMzA0Q0ZCNzBEMjkyMEI5MUUzQUQzRkU1MUFFMEZGNDA0OTE5ODc0OTk1REY5NkRBMDAyQQ==" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=debug msg="fetched chunk 11/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=info msg="prefetched track \"Amor Em Paz (Once I Loved)\" (duration: 214693ms)" uri="spotify:track:7z97VUngFESJNinp9B3znE" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=debug msg="fetched chunk 14/14, size: 35668" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:46 volumio go-librespot[1669]: time="2024-09-02T18:07:46+01:00" level=debug msg="put connect state because NEW_DEVICE" Sep 02 18:07:47 volumio volumio[1327]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 02 18:07:47 volumio volumio[1327]: Error: getaddrinfo ENOTFOUND ws.audioscrobbler.com Sep 02 18:07:47 volumio volumio[1327]: at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:26) { Sep 02 18:07:47 volumio volumio[1327]: errno: -3007, Sep 02 18:07:47 volumio volumio[1327]: code: 'ENOTFOUND', Sep 02 18:07:47 volumio volumio[1327]: syscall: 'getaddrinfo', Sep 02 18:07:47 volumio volumio[1327]: hostname: 'ws.audioscrobbler.com' Sep 02 18:07:47 volumio volumio[1327]: } Sep 02 18:07:47 volumio volumio[1327]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="handling transfer player command from a6bb78d54ee4ae731ced295261db9207e09ac960" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="resolved context of track" uri="spotify:album:3tW43cUkPyYkzzntfPwm4A" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" uri="spotify:album:3tW43cUkPyYkzzntfPwm4A" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="loading track (paused: false, position: 148924ms)" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=trace msg="emitting websocket event: will_play" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="selected format OGG_VORBIS_320 (a008fd20231da1a6d386a634f3d971bdfbe5489f)" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="requested aes key for file a008fd20231da1a6d386a634f3d971bdfbe5489f, gid: 6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="fetched first chunk of 15, total size is 7375700 bytes" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="fetched chunk 14/14, size: 35668" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" Sep 02 18:07:47 volumio sudo[1947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-02 18:06 Sep 02 18:07:47 volumio sudo[1947]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 02 18:07:47 volumio go-librespot[1669]: time="2024-09-02T18:07:47+01:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6ZMrpXuvDO8T13QVrshXlL" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"