-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Fri 2024-11-22 22:00:14 UTC. -- Nov 22 21:59:01 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:01 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:04 volumio go-librespot[1097]: time="2024-11-22T21:59:04Z" level=debug msg="fetched chunk 19/21, size: 524288" Nov 22 21:59:04 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:04 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:07 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:07 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:10 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:10 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:13 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:13 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:16 volumio go-librespot[1097]: time="2024-11-22T21:59:16Z" level=debug msg="fetched chunk 20/21, size: 524288" Nov 22 21:59:16 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:16 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:19 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:19 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:22 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:22 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:25 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:25 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:27 volumio go-librespot[1097]: time="2024-11-22T21:59:27Z" level=debug msg="fetched chunk 21/21, size: 415866" Nov 22 21:59:28 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:28 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:31 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:31 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:34 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:34 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:37 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:38 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:41 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:41 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:44 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:44 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:47 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:47 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:50 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:50 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:53 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:53 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:56 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:56 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 21:59:59 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 21:59:59 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 22:00:02 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 22:00:02 volumio volumio[922]: info: Error connecting to go-librespot Websocket: Error: getaddrinfo ENOTFOUND localhost Nov 22 22:00:05 volumio volumio[922]: info: Initializing connection to go-librespot Websocket Nov 22 22:00:10 volumio go-librespot[1097]: time="2024-11-22T22:00:10Z" level=debug msg="new websocket client" Nov 22 22:00:10 volumio volumio[922]: info: Connection to go-librespot Websocket established Nov 22 22:00:13 volumio volumio[922]: info: Getting Spotify volume Nov 22 22:00:13 volumio volumio[922]: info: Spotify volume: 100 Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=trace msg="emitting websocket event: not_playing" Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=debug msg="loading track spotify:track:2j1aLqsCRdDy16gjjF9ONq (paused: false, position: 0ms)" Nov 22 22:00:13 volumio volumio[922]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:1M39ETXmej4g9EMSeXPUgj","play_origin":"playlist"}} Nov 22 22:00:13 volumio volumio[922]: error: Failed to decode event: not_playing Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=trace msg="emitting websocket event: will_play" Nov 22 22:00:13 volumio volumio[922]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2j1aLqsCRdDy16gjjF9ONq","play_origin":"playlist"}} Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:2j1aLqsCRdDy16gjjF9ONq" Nov 22 22:00:13 volumio go-librespot[1097]: time="2024-11-22T22:00:13Z" level=debug msg="requested aes key for file 2370e7d95589a9951024f8a50c92cf9437038f3f, gid: 2j1aLqsCRdDy16gjjF9ONq" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="fetched first chunk of 13, total size is 6325480 bytes" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Nov 22 22:00:14 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=info msg="loaded track \"Together\" (uri: spotify:track:2j1aLqsCRdDy16gjjF9ONq, paused: false, position: 0ms, duration: 150712ms)" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=trace msg="emitting websocket event: metadata" Nov 22 22:00:14 volumio volumio[922]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2j1aLqsCRdDy16gjjF9ONq","name":"Together","artist_names":["Layup"],"album_name":"Whole New Level - EP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027d7d68d84dfb0b12e5e7fd7d","position":0,"duration":150712,"release_date":"year:2018 month:4 day:20","track_number":6,"disc_number":1}} Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="fetched chunk 1/12, size: 524288" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=trace msg="emitting websocket event: playing" Nov 22 22:00:14 volumio volumio[922]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2j1aLqsCRdDy16gjjF9ONq","play_origin":"playlist"}} Nov 22 22:00:14 volumio volumio[922]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 22 22:00:14 volumio volumio[922]: TypeError: Cannot read property 'service' of undefined Nov 22 22:00:14 volumio volumio[922]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 22 22:00:14 volumio volumio[922]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Nov 22 22:00:14 volumio volumio[922]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 22 22:00:14 volumio volumio[922]: at WebSocket.emit (events.js:315:20) Nov 22 22:00:14 volumio volumio[922]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Nov 22 22:00:14 volumio volumio[922]: at Receiver.emit (events.js:315:20) Nov 22 22:00:14 volumio volumio[922]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Nov 22 22:00:14 volumio volumio[922]: at internal/process/task_queues.js:149:7 Nov 22 22:00:14 volumio volumio[922]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Nov 22 22:00:14 volumio volumio[922]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Nov 22 22:00:14 volumio volumio[922]: at runMicrotasks () Nov 22 22:00:14 volumio volumio[922]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Nov 22 22:00:14 volumio volumio[922]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="fetched chunk 3/12, size: 524288" Nov 22 22:00:14 volumio go-librespot[1097]: time="2024-11-22T22:00:14Z" level=debug msg="fetched chunk 2/12, size: 524288" Nov 22 22:00:14 volumio sudo[6992]: volumio : unable to resolve host volumio Nov 22 22:00:14 volumio sudo[6992]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Nov 22 22:00:14 volumio sudo[6992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-22 21:59 Nov 22 22:00:14 volumio sudo[6992]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"