Jan 25 20:36:05 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:05+05:30" level=trace msg="emitting websocket event: not_playing" Jan 25 20:36:05 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:05+05:30" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:05 volumio-mkm volumio[1242]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","uri":"spotify:track:1Eb90nmqTrxylKFhcUzW8P","play_origin":"go-librespot"}} Jan 25 20:36:05 volumio-mkm volumio[1242]: error: Failed to decode event: not_playing Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=trace msg="emitting websocket event: will_play" Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","play_origin":"go-librespot"}} Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="selected format OGG_VORBIS_320 (42520178ae92d62f69dc288fc1ca418656bfef7c)" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="requested aes key for file 42520178ae92d62f69dc288fc1ca418656bfef7c, gid: 7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 2 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: Prefetching next song Jan 25 20:36:06 volumio-mkm volumio[1242]: info: [1769353566307] ControllerSpotify::prefetch Jan 25 20:36:06 volumio-mkm volumio[1242]: info: Sending Spotify command with payload to local API: /player/add_to_queue Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=trace msg="found 2 cdn urls" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="fetched first chunk of 19, total size is 9624260 bytes" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=info msg="loaded track \"Heaven\" (paused: true, position: 0ms, duration: 243360ms, prefetched: false)" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=trace msg="emitting websocket event: metadata" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=trace msg="emitting websocket event: stopped" Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","name":"Heaven","artist_names":["Bryan Adams"],"album_name":"Reckless (30th Anniversary / Deluxe Edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02cf1fee2a55e98e22bf358512","position":0,"duration":243360,"release_date":"year:1984 month:11 day:5","track_number":4,"disc_number":1}} Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: PUSH STATE SPOTIFY Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: {"status":"stop","service":"spop","title":"Heaven","artist":"Bryan Adams","album":"Reckless (30th Anniversary / Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02cf1fee2a55e98e22bf358512","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::servicePushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::pushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 2 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioPushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 2 Jan 25 20:36:06 volumio-mkm volumio[1242]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Heaven","artist":"Bryan Adams","album":"Reckless (30th Anniversary / Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02cf1fee2a55e98e22bf358512","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 25 20:36:06 volumio-mkm volumio[1242]: verbose: CURRENT POSITION 2 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::syncState stateService stop Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::syncState currentStatus play Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::pushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioPushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::pushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioPushState Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:7Ewz6bJ97vUqk5HdkvguFQ" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 25 20:36:06 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:06+05:30" level=trace msg="emitting websocket event: paused" Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","play_origin":"go-librespot"}} Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: PUSH STATE SPOTIFY Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: {"status":"pause","service":"spop","title":"Heaven","artist":"Bryan Adams","album":"Reckless (30th Anniversary / Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02cf1fee2a55e98e22bf358512","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::servicePushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Heaven","artist":"Bryan Adams","album":"Reckless (30th Anniversary / Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e02cf1fee2a55e98e22bf358512","uri":"spotify:track:7Ewz6bJ97vUqk5HdkvguFQ","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 25 20:36:06 volumio-mkm volumio[1242]: verbose: CURRENT POSITION 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::syncState stateService pause Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::syncState currentStatus stop Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreStateMachine::pushState Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 20:36:06 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioPushState Jan 25 20:36:06 volumio-mkm volumio[1242]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Jan 25 20:36:07 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:07+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 25 20:36:22 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:22+05:30" level=trace msg="sent dealer ping" Jan 25 20:36:22 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:22+05:30" level=trace msg="received dealer pong" Jan 25 20:36:31 volumio-mkm volumio[1242]: verbose: New Socket.io Connection to 192.168.1.105 from 192.168.1.101 UA: Mozilla/5.0 (Linux; Android 15; 23027RAD4I Build/AQ3A.240829.003; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.59 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetVisibleSources Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetState Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetQueue Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreStateMachine::getQueue Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CorePlayQueue::getQueue Jan 25 20:36:31 volumio-mkm volumio[1242]: info: Listing playlists Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 25 20:36:31 volumio-mkm volumio[1242]: info: Received Get System Info Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 25 20:36:31 volumio-mkm volumio[1242]: info: Discovery: Getting this device information Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetState Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetState Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:31 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 25 20:36:32 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 25 20:36:48 volumio-mkm volumio[1242]: info: Discovery: Getting this device information Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::volumioGetState Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CorePlayQueue::getTrack 3 Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 25 20:36:48 volumio-mkm volumio[1242]: verbose: New Socket.io Connection to 192.168.1.105:3000 from 192.168.1.101 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 25 20:36:48 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 25 20:36:52 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:52+05:30" level=trace msg="sent dealer ping" Jan 25 20:36:52 volumio-mkm go-librespot[1540]: time="2026-01-25T20:36:52+05:30" level=trace msg="received dealer pong" Jan 25 20:37:07 volumio-mkm volumio[1242]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 25 20:37:07 volumio-mkm volumio[1242]: info: In handleBrowseUri, curUri=spotify:artist:3MzD3PInaeXwQZmOgjeFX4 Jan 25 20:37:08 volumio-mkm volumio[1242]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 20:37:08 volumio-mkm volumio[1242]: TypeError: Cannot read properties of undefined (reading 'url') Jan 25 20:37:08 volumio-mkm volumio[1242]: at /data/plugins/music_service/spop/index.js:2449:60 Jan 25 20:37:08 volumio-mkm volumio[1242]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Jan 25 20:37:08 volumio-mkm volumio[1242]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 20:37:08 volumio-mkm sudo[22185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 20:36' Jan 25 20:37:08 volumio-mkm sudo[22185]: 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"