Jan 28 15:11:13 musikbox-mira volumio[1481]: Searching plugin music_service/webradio Jan 28 15:11:13 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 28 15:11:13 musikbox-mira volumio[1481]: info: All search sources collected, pushing search results Jan 28 15:11:15 musikbox-mira volumio[1481]: Searching plugin music_service/webradio Jan 28 15:11:15 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 28 15:11:16 musikbox-mira volumio[1481]: info: All search sources collected, pushing search results Jan 28 15:11:16 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:16+01:00" level=trace msg="received accesspoint ping" Jan 28 15:11:16 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:16+01:00" level=trace msg="received accesspoint pong ack" Jan 28 15:11:16 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:16+01:00" level=trace msg="sent dealer ping" Jan 28 15:11:16 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:16+01:00" level=trace msg="received dealer pong" Jan 28 15:11:17 musikbox-mira volumio[1481]: Searching plugin music_service/webradio Jan 28 15:11:17 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jan 28 15:11:18 musikbox-mira volumio[1481]: info: All search sources collected, pushing search results Jan 28 15:11:20 musikbox-mira volumio[1481]: info: Saving local item radio-favourites Jan 28 15:11:20 musikbox-mira volumio[1481]: info: Pushing Favourites {"uri":"http://opml.radiotime.com/Tune.ashx?id=s15439","favourite":false} Jan 28 15:11:23 musikbox-mira volumio[1481]: info: Saving local item radio-favourites Jan 28 15:11:23 musikbox-mira volumio[1481]: info: Pushing Favourites {"uri":"http://opml.radiotime.com/Tune.ashx?id=s102911","favourite":false} Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="dealer connection closed" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="dealer recv loop stopped" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="obtained new client token: AABzZhLMONFVTm4sMvxf6yeqz2TCBF67LKuCqF6iBfgTQ/qoZAz2PoQFror23QZUVKwbQmCMTvc/+Vd+4YJUaJteN+Gdzq5D3whgFgsTlrt9edpYz2+1yJETIoGo8cV/Zs6KId9o6UCxoruabdvxkfGKs3THWPMu6vxks2teAtEt6BPfnArz5M9K6Cc4+hJ55Oeuylh+HLWMbqPij2bLA5eAlRPomD2VplWH5y98K9fN/e+q1tG0TosP" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="completed keyexchange" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="completed challenge" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=info msg="authenticated AP" username="m8*********************fn" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=info msg="authenticated Login5" username="m8*********************fn" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=info msg="accepted zeroconf from iPhone" username="m8*********************fn" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="dealer connection opened" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=trace msg="starting accesspoint recv loop" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=trace msg="starting dealer recv loop" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=trace msg="received accesspoint ping" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="received connection id: MTM1ZjNmZmUtY2Ew...M0FBRTc1OUNDMg==" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=trace msg="received accesspoint pong ack" Jan 28 15:11:42 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:42+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="handling transfer player command from e6f6b689c1b1ba59cff9174ed4e91bf85b7e3b64" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO2k8YdG" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DZ06evO2k8YdG" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=trace msg="emitting websocket event: will_play" Jan 28 15:11:43 musikbox-mira volumio[1481]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DZ06evO2k8YdG","uri":"spotify:track:0gLEDVr1QbNtqTR00P1D8N","play_origin":"voice-assistant-siri"}} Jan 28 15:11:43 musikbox-mira volumio[1481]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DZ06evO2k8YdG","uri":"spotify:track:0gLEDVr1QbNtqTR00P1D8N","play_origin":"voice-assistant-siri"}} Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1694" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="selected format OGG_VORBIS_320 (33f5279b65f0285d1f47c077c1921ca3ccb1e412)" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="requested aes key for file 33f5279b65f0285d1f47c077c1921ca3ccb1e412, gid: 0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1294" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="fetched first chunk of 20, total size is 10288344 bytes" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="created new output device" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: ALSA lib confmisc.c:165:(snd_config_get_card) Cannot get card index for sndrpihifiberry Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:0gLEDVr1QbNtqTR00P1D8N: ALSA error at snd_pcm_open: No such device" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:43 musikbox-mira go-librespot[8687]: time="2026-01-28T15:11:43+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0gLEDVr1QbNtqTR00P1D8N" Jan 28 15:11:58 musikbox-mira kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Command time (outvact): 33 Jan 28 15:11:58 musikbox-mira kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Jan 28 15:12:04 musikbox-mira volumio[1481]: info: CoreCommandRouter::volumioGetQueue Jan 28 15:12:04 musikbox-mira volumio[1481]: info: CoreStateMachine::getQueue Jan 28 15:12:04 musikbox-mira volumio[1481]: info: CorePlayQueue::getQueue Jan 28 15:12:08 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 28 15:12:08 musikbox-mira volumio[1481]: info: In handleBrowseUri, curUri=spotify Jan 28 15:12:09 musikbox-mira volumio[1481]: info: Preload queue cleared Jan 28 15:12:09 musikbox-mira volumio[1481]: info: Preload queue cleared Jan 28 15:12:09 musikbox-mira volumio[1481]: info: Preload queue cleared Jan 28 15:12:09 musikbox-mira volumio[1481]: info: Preload queue cleared Jan 28 15:12:11 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 28 15:12:11 musikbox-mira volumio[1481]: info: In handleBrowseUri, curUri=spotify/playlists Jan 28 15:12:11 musikbox-mira volumio[1481]: info: Preload queue cleared Jan 28 15:12:12 musikbox-mira go-librespot[8687]: time="2026-01-28T15:12:12+01:00" level=trace msg="sent dealer ping" Jan 28 15:12:12 musikbox-mira go-librespot[8687]: time="2026-01-28T15:12:12+01:00" level=trace msg="received dealer pong" Jan 28 15:12:14 musikbox-mira volumio[1481]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 28 15:12:14 musikbox-mira volumio[1481]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:4ZsoujBNKQIW2gohBuz7wV Jan 28 15:12:14 musikbox-mira volumio[1481]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 15:12:14 musikbox-mira volumio[1481]: TypeError: Cannot read properties of null (reading '0') Jan 28 15:12:14 musikbox-mira volumio[1481]: at /data/plugins/music_service/spop/index.js:2504:56 Jan 28 15:12:14 musikbox-mira volumio[1481]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Jan 28 15:12:14 musikbox-mira volumio[1481]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 15:12:14 musikbox-mira sudo[8990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 15:11' Jan 28 15:12:14 musikbox-mira sudo[8990]: 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"