Dec 17 08:03:03 volumio2 go-librespot[1790]: time="2025-12-17T08:03:03+13:00" level=debug msg="fetched chunk 16/16, size: 430832" uri="spotify:track:2m5xo4HEFHgOQpqqrxCS5u" Dec 17 08:03:08 volumio2 go-librespot[1790]: time="2025-12-17T08:03:08+13:00" level=trace msg="sent dealer ping" Dec 17 08:03:08 volumio2 go-librespot[1790]: time="2025-12-17T08:03:08+13:00" level=trace msg="received dealer pong" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="prefetching next track" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="selected format OGG_VORBIS_320 (37a3613e01da97912c590adbe10876f56bedc1de)" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="requested aes key for file 37a3613e01da97912c590adbe10876f56bedc1de, gid: 5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="fetched first chunk of 33, total size is 17151044 bytes" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=info msg="prefetched track \"Year of the Cat - 2001 Remaster\" (duration: 401400ms)" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="fetched chunk 1/32, size: 524288" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:26 volumio2 go-librespot[1790]: time="2025-12-17T08:03:26+13:00" level=debug msg="fetched chunk 2/32, size: 524288" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:27 volumio2 go-librespot[1790]: time="2025-12-17T08:03:27+13:00" level=debug msg="fetched chunk 3/32, size: 524288" uri="spotify:track:5jYYumalS1qELrcChOCZrK" Dec 17 08:03:37 volumio2 go-librespot[1790]: time="2025-12-17T08:03:37+13:00" level=trace msg="received accesspoint ping" Dec 17 08:03:37 volumio2 go-librespot[1790]: time="2025-12-17T08:03:37+13:00" level=trace msg="received accesspoint pong ack" Dec 17 08:03:38 volumio2 go-librespot[1790]: time="2025-12-17T08:03:38+13:00" level=trace msg="sent dealer ping" Dec 17 08:03:38 volumio2 go-librespot[1790]: time="2025-12-17T08:03:38+13:00" level=trace msg="received dealer pong" Dec 17 08:03:50 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 34 Dec 17 08:03:50 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:50 volumio2 volumio[1318]: info: Prefetching next song Dec 17 08:03:50 volumio2 volumio[1318]: info: [1765911830510] ControllerSpotify::prefetch Dec 17 08:03:50 volumio2 volumio[1318]: info: Sending Spotify command with payload to local API: /player/add_to_queue Dec 17 08:03:50 volumio2 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 17 08:03:50 volumio2 go-librespot[1790]: time="2025-12-17T08:03:50+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 08:03:50 volumio2 go-librespot[1790]: time="2025-12-17T08:03:50+13:00" level=debug msg="prefetching next track" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:50 volumio2 go-librespot[1790]: time="2025-12-17T08:03:50+13:00" level=warning msg="original track has no formats, alternatives have a total of 4" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:50 volumio2 go-librespot[1790]: time="2025-12-17T08:03:50+13:00" level=debug msg="selected format OGG_VORBIS_320 (526ed8d45b2a7a6f69ca1783be720232edbb6714)" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:50 volumio2 go-librespot[1790]: time="2025-12-17T08:03:50+13:00" level=debug msg="requested aes key for file 526ed8d45b2a7a6f69ca1783be720232edbb6714, gid: 5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:51 volumio2 systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 17 08:03:51 volumio2 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 17 08:03:51 volumio2 go-librespot[1790]: time="2025-12-17T08:03:51+13:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:51 volumio2 go-librespot[1790]: time="2025-12-17T08:03:51+13:00" level=debug msg="fetched first chunk of 25, total size is 12679280 bytes" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:52 volumio2 go-librespot[1790]: time="2025-12-17T08:03:52+13:00" level=info msg="prefetched track \"(I've Had) The Time of My Life\" (duration: 289680ms)" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:52 volumio2 go-librespot[1790]: time="2025-12-17T08:03:52+13:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:52 volumio2 go-librespot[1790]: time="2025-12-17T08:03:52+13:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:52 volumio2 go-librespot[1790]: time="2025-12-17T08:03:52+13:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:55 volumio2 volumio[1318]: info: CoreStateMachine::startPlaybackTimer Dec 17 08:03:55 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:55 volumio2 volumio[1318]: info: CoreStateMachine::pushState Dec 17 08:03:55 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:55 volumio2 volumio[1318]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 08:03:55 volumio2 volumio[1318]: info: CoreCommandRouter::volumioPushState Dec 17 08:03:55 volumio2 volumio[1318]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 17 08:03:55 volumio2 go-librespot[1790]: time="2025-12-17T08:03:55+13:00" level=trace msg="emitting websocket event: not_playing" Dec 17 08:03:55 volumio2 volumio[1318]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:station:track:2I5ga2ye1qk4tXMQntXlKe","uri":"spotify:track:2m5xo4HEFHgOQpqqrxCS5u","play_origin":"go-librespot"}} Dec 17 08:03:55 volumio2 volumio[1318]: error: Failed to decode event: not_playing Dec 17 08:03:55 volumio2 go-librespot[1790]: time="2025-12-17T08:03:55+13:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=trace msg="emitting websocket event: will_play" Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:station:track:2I5ga2ye1qk4tXMQntXlKe","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","play_origin":"go-librespot"}} Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=info msg="loaded track \"(I've Had) The Time of My Life\" (paused: false, position: 0ms, duration: 289680ms, prefetched: true)" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=trace msg="scheduling prefetch in 260s" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=trace msg="emitting websocket event: metadata" Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","name":"(I've Had) The Time of My Life","artist_names":["Bill Medley","Jennifer Warnes"],"album_name":"Dirty Dancing","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02741a375f2292fbe848ef27e8","position":0,"duration":289680,"release_date":"year:1987 month:7 day:10","track_number":1,"disc_number":1}} Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 08:03:56 volumio2 go-librespot[1790]: time="2025-12-17T08:03:56+13:00" level=trace msg="emitting websocket event: playing" Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:station:track:2I5ga2ye1qk4tXMQntXlKe","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","resume":false,"play_origin":"go-librespot"}} Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: PUSH STATE SPOTIFY Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: {"status":"play","service":"spop","title":"(I've Had) The Time of My Life","artist":"Bill Medley, Jennifer Warnes","album":"Dirty Dancing","albumart":"https://i.scdn.co/image/ab67616d00001e02741a375f2292fbe848ef27e8","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","trackType":"spotify","seek":1000,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::servicePushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"(I've Had) The Time of My Life","artist":"Bill Medley, Jennifer Warnes","album":"Dirty Dancing","albumart":"https://i.scdn.co/image/ab67616d00001e02741a375f2292fbe848ef27e8","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","trackType":"spotify","seek":1000,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 17 08:03:56 volumio2 volumio[1318]: verbose: CURRENT POSITION 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::syncState stateService play Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::syncState currentStatus play Dec 17 08:03:56 volumio2 volumio[1318]: info: Received an update from plugin. extracting info from payload Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::pushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::volumioPushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::pushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::volumioPushState Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: PUSH STATE SPOTIFY Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: {"status":"play","service":"spop","title":"(I've Had) The Time of My Life","artist":"Bill Medley, Jennifer Warnes","album":"Dirty Dancing","albumart":"https://i.scdn.co/image/ab67616d00001e02741a375f2292fbe848ef27e8","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","trackType":"spotify","seek":1000,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::servicePushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"(I've Had) The Time of My Life","artist":"Bill Medley, Jennifer Warnes","album":"Dirty Dancing","albumart":"https://i.scdn.co/image/ab67616d00001e02741a375f2292fbe848ef27e8","uri":"spotify:track:5UqqOfFa9DYXALpCCF8VwB","trackType":"spotify","seek":1000,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 17 08:03:56 volumio2 volumio[1318]: verbose: CURRENT POSITION 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::syncState stateService play Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::syncState currentStatus play Dec 17 08:03:56 volumio2 volumio[1318]: info: Received an update from plugin. extracting info from payload Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::pushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::volumioPushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreStateMachine::pushState Dec 17 08:03:56 volumio2 volumio[1318]: info: CorePlayQueue::getTrack 26 Dec 17 08:03:56 volumio2 volumio[1318]: info: CoreCommandRouter::volumioPushState Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 17 08:03:56 volumio2 volumio[1318]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Dec 17 08:04:08 volumio2 go-librespot[1790]: time="2025-12-17T08:04:08+13:00" level=trace msg="sent dealer ping" Dec 17 08:04:08 volumio2 go-librespot[1790]: time="2025-12-17T08:04:08+13:00" level=trace msg="received dealer pong" Dec 17 08:04:08 volumio2 go-librespot[1790]: time="2025-12-17T08:04:08+13:00" level=debug msg="fetched chunk 4/24, size: 524288" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:04:12 volumio2 volumio[1318]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 17 08:04:12 volumio2 volumio[1318]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 17 08:04:21 volumio2 go-librespot[1790]: time="2025-12-17T08:04:21+13:00" level=debug msg="fetched chunk 5/24, size: 524288" uri="spotify:track:5UqqOfFa9DYXALpCCF8VwB" Dec 17 08:04:26 volumio2 volumio[1318]: info: Starting Uninstall of plugin user_interface - touch_display Dec 17 08:04:26 volumio2 volumio[1318]: info: Uninstalling plugin touch_display Dec 17 08:04:27 volumio2 sudo[27316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Dec 17 08:04:27 volumio2 sudo[27316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 08:04:27 volumio2 sudo[27316]: pam_unix(sudo:session): session closed for user root Dec 17 08:04:27 volumio2 volumio[1318]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Dec 17 08:04:27 volumio2 volumio[1318]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 08:04:27 volumio2 sudo[27322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable getty@tty1.service Dec 17 08:04:27 volumio2 sudo[27322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 08:04:27 volumio2 sudo[27319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start getty@tty1.service Dec 17 08:04:27 volumio2 sudo[27319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 08:04:27 volumio2 sudo[27323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service Dec 17 08:04:27 volumio2 volumio[1318]: TypeError: Cannot read properties of undefined (reading 'split') Dec 17 08:04:27 volumio2 volumio[1318]: at /data/plugins/user_interface/touch_display/index.js:1298:37 Dec 17 08:04:27 volumio2 volumio[1318]: at ChildProcess.exithandler (node:child_process:413:7) Dec 17 08:04:27 volumio2 volumio[1318]: at ChildProcess.emit (node:events:514:28) Dec 17 08:04:27 volumio2 volumio[1318]: at maybeClose (node:internal/child_process:1105:16) Dec 17 08:04:27 volumio2 volumio[1318]: at Socket. (node:internal/child_process:457:11) Dec 17 08:04:27 volumio2 volumio[1318]: at Socket.emit (node:events:514:28) Dec 17 08:04:27 volumio2 volumio[1318]: at Pipe. (node:net:337:12) Dec 17 08:04:27 volumio2 volumio[1318]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 08:04:27 volumio2 sudo[27323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 08:04:27 volumio2 systemd[1]: Reloading. Dec 17 08:04:27 volumio2 sudo[27358]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-17 08:03' Dec 17 08:04:27 volumio2 sudo[27358]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"