Feb 22 17:48:25 volumio4 go-librespot[18702]: time="2026-02-22T17:48:25-05:00" level=trace msg="sent dealer ping" Feb 22 17:48:26 volumio4 go-librespot[18702]: time="2026-02-22T17:48:26-05:00" level=trace msg="received dealer pong" Feb 22 17:48:28 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 30 Feb 22 17:48:28 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 31 Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="emitting websocket event: not_playing" Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","uri":"spotify:track:6YbfTiImEm6kH6gRXpdtgR","play_origin":"go-librespot"}} Feb 22 17:48:32 volumio4 volumio[18506]: error: Failed to decode event: not_playing Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="emitting websocket event: will_play" Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","play_origin":"go-librespot"}} Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="selected format OGG_VORBIS_320 (0c4a611c478dab266dece942bd9eac2438c6bdb4)" uri="spotify:track:77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="requested aes key for file 0c4a611c478dab266dece942bd9eac2438c6bdb4, gid: 77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="found 2 cdn urls" uri="spotify:track:77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="fetched first chunk of 1, total size is 508512 bytes" uri="spotify:track:77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=info msg="loaded track \"Donuts (Outro)\" (paused: true, position: 0ms, duration: 12666ms, prefetched: false)" uri="spotify:track:77cVT85pU7WH3elC1SE7Uu" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="emitting websocket event: metadata" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="emitting websocket event: stopped" Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","name":"Donuts (Outro)","artist_names":["J Dilla"],"album_name":"Donuts","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0283bb78285449998bb974da45","position":0,"duration":12666,"release_date":"year:2006 month:2 day:7","track_number":1,"disc_number":1}} Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: PUSH STATE SPOTIFY Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: {"status":"stop","service":"spop","title":"Donuts (Outro)","artist":"J Dilla","album":"Donuts","albumart":"https://i.scdn.co/image/ab67616d00001e0283bb78285449998bb974da45","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","trackType":"spotify","seek":0,"duration":12,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::servicePushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: CoreStateMachine::syncState Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::pushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: CoreStateMachine::getState Feb 22 17:48:32 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 30 Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: API:pushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: No callbacks for volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 30 Feb 22 17:48:32 volumio4 volumio[18506]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Donuts (Outro)","artist":"J Dilla","album":"Donuts","albumart":"https://i.scdn.co/image/ab67616d00001e0283bb78285449998bb974da45","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","trackType":"spotify","seek":0,"duration":12,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 22 17:48:32 volumio4 volumio[18506]: verbose: CURRENT POSITION 30 Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::syncState stateService stop Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::syncState currentStatus play Feb 22 17:48:32 volumio4 volumio[18506]: debug: CURRENT POSITION 30 Feb 22 17:48:32 volumio4 volumio[18506]: debug: CURRENT POSITION 31 Feb 22 17:48:32 volumio4 volumio[18506]: debug: END OF QUEUE Feb 22 17:48:32 volumio4 volumio[18506]: debug: CoreStateMachine::pushEmptyState Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: API:pushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: No callbacks for volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::stPlaybackTimer Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 17:48:32 volumio4 go-librespot[18702]: time="2026-02-22T17:48:32-05:00" level=trace msg="emitting websocket event: paused" Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","play_origin":"go-librespot"}} Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: PUSH STATE SPOTIFY Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: {"status":"pause","service":"spop","title":"Donuts (Outro)","artist":"J Dilla","album":"Donuts","albumart":"https://i.scdn.co/image/ab67616d00001e0283bb78285449998bb974da45","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","trackType":"spotify","seek":0,"duration":12,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::servicePushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: CoreStateMachine::syncState Feb 22 17:48:32 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 0 Feb 22 17:48:32 volumio4 volumio[18506]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Donuts (Outro)","artist":"J Dilla","album":"Donuts","albumart":"https://i.scdn.co/image/ab67616d00001e0283bb78285449998bb974da45","uri":"spotify:track:77cVT85pU7WH3elC1SE7Uu","trackType":"spotify","seek":0,"duration":12,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 22 17:48:32 volumio4 volumio[18506]: verbose: CURRENT POSITION 0 Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::syncState stateService pause Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::syncState currentStatus stop Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreStateMachine::pushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: CoreStateMachine::getState Feb 22 17:48:32 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 0 Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 17:48:32 volumio4 volumio[18506]: info: CoreCommandRouter::volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: API:pushState Feb 22 17:48:32 volumio4 volumio[18506]: debug: No callbacks for volumioPushState Feb 22 17:48:32 volumio4 volumio[18506]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Feb 22 17:48:55 volumio4 go-librespot[18702]: time="2026-02-22T17:48:55-05:00" level=trace msg="sent dealer ping" Feb 22 17:48:56 volumio4 go-librespot[18702]: time="2026-02-22T17:48:56-05:00" level=trace msg="received dealer pong" Feb 22 17:49:12 volumio4 volumio[18506]: verbose: New Socket.io Connection to 192.168.1.142 from 192.168.1.179 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::volumioGetVisibleSources Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::volumioGetState Feb 22 17:49:12 volumio4 volumio[18506]: debug: CoreStateMachine::getState Feb 22 17:49:12 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 0 Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 22 17:49:12 volumio4 volumio[18506]: info: Received Get System Info Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 17:49:12 volumio4 volumio[18506]: info: Discovery: Getting this device information Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::volumioGetState Feb 22 17:49:12 volumio4 volumio[18506]: debug: CoreStateMachine::getState Feb 22 17:49:12 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 0 Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::volumioGetState Feb 22 17:49:12 volumio4 volumio[18506]: debug: CoreStateMachine::getState Feb 22 17:49:12 volumio4 volumio[18506]: info: CorePlayQueue::getTrack 0 Feb 22 17:49:12 volumio4 volumio[18506]: info: Listing playlists Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreCommandRouter::volumioGetQueue Feb 22 17:49:12 volumio4 volumio[18506]: info: CoreStateMachine::getQueue Feb 22 17:49:12 volumio4 volumio[18506]: info: CorePlayQueue::getQueue Feb 22 17:49:16 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 22 17:49:16 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 22 17:49:18 volumio4 volumio[18506]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 22 17:49:22 volumio4 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 22 17:49:23 volumio4 systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 22 17:49:23 volumio4 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 22 17:49:25 volumio4 go-librespot[18702]: time="2026-02-22T17:49:25-05:00" level=trace msg="received accesspoint ping" Feb 22 17:49:25 volumio4 go-librespot[18702]: time="2026-02-22T17:49:25-05:00" level=trace msg="received accesspoint pong ack" Feb 22 17:49:25 volumio4 go-librespot[18702]: time="2026-02-22T17:49:25-05:00" level=trace msg="sent dealer ping" Feb 22 17:49:26 volumio4 go-librespot[18702]: time="2026-02-22T17:49:26-05:00" level=trace msg="received dealer pong" Feb 22 17:49:41 volumio4 volumio[18506]: info: CALLMETHOD: user_interface upc_search searchAlbumArtist [object Object] Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: upc_search , searchAlbumArtist Feb 22 17:49:41 volumio4 volumio[18506]: debug: UPC_SEARCH::searchAlbumArtist got state: Feb 22 17:49:41 volumio4 volumio[18506]: debug: {"artist":"Evelyne","album":"Test pattern"} Feb 22 17:49:41 volumio4 volumio[18506]: debug: UPC_SEARCH::searchAlbumArtist emitting 'search' with data: Feb 22 17:49:41 volumio4 volumio[18506]: {"value":"evelyne test pattern"} Feb 22 17:49:41 volumio4 volumio[18506]: Searching all installed plugins Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: , search Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: mpd , search Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: webradio , search Feb 22 17:49:41 volumio4 volumio[18506]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 22 17:49:42 volumio4 volumio[18506]: info: All search sources collected, pushing search results Feb 22 17:49:42 volumio4 volumio[18506]: debug: Response! Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::onSearchResults got data Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::onSearchResults extracted raw albums: Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::onSearchResults local albums: Feb 22 17:49:42 volumio4 volumio[18506]: debug: None! Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::subdivideString attempting to shorten evelyne Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::subdivideString results evelyne Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::subdivideString attempting to shorten test pattern Feb 22 17:49:42 volumio4 volumio[18506]: debug: UPC_SEARCH::subdivideString results test pattern Feb 22 17:49:42 volumio4 volumio[18506]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 22 17:49:42 volumio4 volumio[18506]: TypeError: Cannot read properties of null (reading 'length') Feb 22 17:49:42 volumio4 volumio[18506]: at upcSearch.onSearchResults (/data/plugins/user_interface/upc_search/index.js:516:29) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket. (/data/plugins/user_interface/upc_search/index.js:373:8) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket.on (/data/plugins/user_interface/upc_search/node_modules/component-emitter/index.js:65:8) Feb 22 17:49:42 volumio4 volumio[18506]: at Emitter.emit (/data/plugins/user_interface/upc_search/node_modules/component-emitter/index.js:145:20) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket.onevent (/data/plugins/user_interface/upc_search/node_modules/socket.io-client/lib/socket.js:278:10) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket.onpacket (/data/plugins/user_interface/upc_search/node_modules/socket.io-client/lib/socket.js:236:12) Feb 22 17:49:42 volumio4 volumio[18506]: at Manager. (/data/plugins/user_interface/upc_search/node_modules/component-bind/index.js:21:15) Feb 22 17:49:42 volumio4 volumio[18506]: at Emitter.emit (/data/plugins/user_interface/upc_search/node_modules/component-emitter/index.js:145:20) Feb 22 17:49:42 volumio4 volumio[18506]: at Manager.ondecoded (/data/plugins/user_interface/upc_search/node_modules/socket.io-client/lib/manager.js:349:8) Feb 22 17:49:42 volumio4 volumio[18506]: at Decoder. (/data/plugins/user_interface/upc_search/node_modules/component-bind/index.js:21:15) Feb 22 17:49:42 volumio4 volumio[18506]: at Emitter.emit (/data/plugins/user_interface/upc_search/node_modules/component-emitter/index.js:145:20) Feb 22 17:49:42 volumio4 volumio[18506]: at Decoder.add (/data/plugins/user_interface/upc_search/node_modules/socket.io-parser/index.js:254:12) Feb 22 17:49:42 volumio4 volumio[18506]: at Manager.ondata (/data/plugins/user_interface/upc_search/node_modules/socket.io-client/lib/manager.js:339:16) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket. (/data/plugins/user_interface/upc_search/node_modules/component-bind/index.js:21:15) Feb 22 17:49:42 volumio4 volumio[18506]: at Emitter.emit (/data/plugins/user_interface/upc_search/node_modules/component-emitter/index.js:145:20) Feb 22 17:49:42 volumio4 volumio[18506]: at Socket.onPacket (/data/plugins/user_interface/upc_search/node_modules/engine.io-client/lib/socket.js:461:14) Feb 22 17:49:42 volumio4 volumio[18506]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 22 17:49:43 volumio4 sudo[23129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-22 17:48' Feb 22 17:49:43 volumio4 sudo[23129]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"