May 28 22:06:01 volumio bluealsa[961]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_75_E7_AF_54_62_65, ...) May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:01 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:01 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.178.5:3000 from 192.168.178.68 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 28 22:06:01 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 28 22:06:02 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 28 22:06:03 volumio bluealsa[961]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_73_43_72_B8_D8_51, ...) May 28 22:06:03 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:06:03 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify May 28 22:06:03 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:03 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:03 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:03 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:05 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:06:05 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify/playlists May 28 22:06:05 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:10 volumio volumio[1215]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 28 22:06:10 volumio volumio[1215]: info: Received Get System Version May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 28 22:06:10 volumio volumio[1215]: info: Received Get System Info May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:10 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:10 volumio sudo[2460]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 28 22:06:10 volumio sudo[2458]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 28 22:06:10 volumio sudo[2458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:10 volumio sudo[2460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:10 volumio sudo[2458]: pam_unix(sudo:session): session closed for user root May 28 22:06:10 volumio sudo[2460]: pam_unix(sudo:session): session closed for user root May 28 22:06:10 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.178.5 from 192.168.178.68 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::getUIConfigOnPlugin May 28 22:06:10 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 28 22:06:11 volumio volumio[1215]: info: Received Get System Info May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:11 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:11 volumio volumio[1215]: info: Listing playlists May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 28 22:06:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 28 22:06:12 volumio volumio[1215]: info: Received Get System Version May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:12 volumio volumio[1215]: info: Received Get System Info May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:12 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 28 22:06:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:13 volumio volumio[1215]: info: Received Get System Info May 28 22:06:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:13 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:13 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:14 volumio go-librespot[1605]: time="2026-05-28T22:06:14+02:00" level=trace msg="sent dealer ping" May 28 22:06:14 volumio go-librespot[1605]: time="2026-05-28T22:06:14+02:00" level=trace msg="received dealer pong" May 28 22:06:18 volumio volumio[1215]: info: CALLMETHOD: system_controller system saveGeneralSettings [object Object] May 28 22:06:18 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , saveGeneralSettings May 28 22:06:20 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 28 22:06:22 volumio volumio[1215]: info: CALLMETHOD: miscellanea appearance setVolumio3UI [object Object] May 28 22:06:22 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , setVolumio3UI May 28 22:06:22 volumio volumio[1215]: info: Setting active UI to: {"uiPrettyName":"Manifest","uiName":"manifest","uiPath":"/volumio/http/www4"} May 28 22:06:23 volumio volumio[1215]: info: CoreCommandRouter::Reload Ui May 28 22:06:23 volumio sudo[2525]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 28 22:06:23 volumio sudo[2525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:23 volumio sudo[2525]: pam_unix(sudo:session): session closed for user root May 28 22:06:23 volumio sudo[2531]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 28 22:06:23 volumio sudo[2531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:23 volumio sudo[2527]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 28 22:06:23 volumio sudo[2527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:23 volumio sudo[2531]: pam_unix(sudo:session): session closed for user root May 28 22:06:23 volumio sudo[2532]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 28 22:06:23 volumio sudo[2532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 28 22:06:23 volumio sudo[2527]: pam_unix(sudo:session): session closed for user root May 28 22:06:23 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.178.5 from 192.168.178.126 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/148.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 May 28 22:06:23 volumio sudo[2532]: pam_unix(sudo:session): session closed for user root May 28 22:06:23 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.178.5 from 192.168.178.68 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 28 22:06:23 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetQueue May 28 22:06:24 volumio volumio[1215]: info: CoreStateMachine::getQueue May 28 22:06:24 volumio volumio[1215]: info: CorePlayQueue::getQueue May 28 22:06:24 volumio volumio[1215]: info: Listing playlists May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 28 22:06:24 volumio volumio[1215]: info: Received Get System Info May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:24 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 28 22:06:24 volumio volumio[1215]: info: Received Get System Info May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:24 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:24 volumio volumio[1215]: info: Listing playlists May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:25 volumio volumio[1215]: info: Received Get System Info May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:25 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:25 volumio volumio[1215]: info: Received Get System Info May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:25 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:25 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:26 volumio volumio[1215]: info: Received Get System Info May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:26 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:06:26 volumio volumio[1215]: info: Received Get System Info May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:26 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:26 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:28 volumio volumio[1215]: info: CoreCommandRouter::volumioGetQueue May 28 22:06:28 volumio volumio[1215]: info: CoreStateMachine::getQueue May 28 22:06:28 volumio volumio[1215]: info: CorePlayQueue::getQueue May 28 22:06:33 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 28 22:06:33 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 28 22:06:34 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:06:34 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify May 28 22:06:34 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:34 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:34 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:34 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:36 volumio bluealsa[961]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_75_E7_AF_54_62_65, ...) May 28 22:06:37 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:06:37 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify/myalbums May 28 22:06:37 volumio volumio[1215]: info: Preload queue cleared May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:41 volumio volumio[1215]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 28 22:06:41 volumio volumio[1215]: info: Received Get System Version May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 28 22:06:41 volumio volumio[1215]: info: Received Get System Info May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:41 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:06:41 volumio volumio[1215]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 28 22:06:41 volumio volumio[1215]: info: Received Get System Version May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 28 22:06:41 volumio volumio[1215]: info: Received Get System Info May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:06:41 volumio volumio[1215]: info: Discovery: Getting this device information May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:06:41 volumio volumio[1215]: Searching plugin music_service/spop May 28 22:06:41 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , search May 28 22:06:42 volumio volumio[1215]: info: All search sources collected, pushing search results May 28 22:06:43 volumio go-librespot[1605]: time="2026-05-28T22:06:43+02:00" level=trace msg="received accesspoint ping" May 28 22:06:43 volumio go-librespot[1605]: time="2026-05-28T22:06:43+02:00" level=trace msg="received accesspoint pong ack" May 28 22:06:44 volumio go-librespot[1605]: time="2026-05-28T22:06:44+02:00" level=trace msg="sent dealer ping" May 28 22:06:44 volumio go-librespot[1605]: time="2026-05-28T22:06:44+02:00" level=trace msg="received dealer pong" May 28 22:06:47 volumio volumio[1215]: Searching plugin music_service/spop May 28 22:06:47 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , search May 28 22:06:48 volumio volumio[1215]: info: All search sources collected, pushing search results May 28 22:06:48 volumio volumio[1215]: Searching plugin music_service/spop May 28 22:06:48 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , search May 28 22:06:48 volumio volumio[1215]: info: All search sources collected, pushing search results May 28 22:06:49 volumio volumio[1215]: Searching plugin music_service/spop May 28 22:06:49 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , search May 28 22:06:50 volumio volumio[1215]: info: All search sources collected, pushing search results May 28 22:06:52 volumio volumio[1215]: Searching plugin music_service/spop May 28 22:06:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , search May 28 22:06:53 volumio volumio[1215]: info: All search sources collected, pushing search results May 28 22:07:05 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:07:05 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify:artist:5PckNjzPsNvzkFLTx6IZcA May 28 22:07:06 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:06 volumio volumio[1215]: info: Preloading song: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:06 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:06 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:07 volumio volumio[1215]: info: No valid Plugin REST Endpoint May 28 22:07:14 volumio go-librespot[1605]: time="2026-05-28T22:07:14+02:00" level=trace msg="sent dealer ping" May 28 22:07:14 volumio go-librespot[1605]: time="2026-05-28T22:07:14+02:00" level=trace msg="received dealer pong" May 28 22:07:14 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioReplaceandPlayItems May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::ClearQueue May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::stPlaybackTimer May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::serviceStop May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::serviceStop May 28 22:07:14 volumio volumio[1215]: info: [1779998834643] ControllerWebradio::stop May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand stop May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::clearPlayQueue May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:14 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:0zimaaqW0UrEnGnPIlMufD in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.652+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.654+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id=http://mscp3.live-streams.nl:8250/class-flac.flac title="Naim Classical (FLAC)" May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: info: May 28 22:07:14 volumio volumio[1215]: ---------------------------- MPD announces state update: player May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand stop took 23 milliseconds May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::getState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand status May 28 22:07:14 volumio volumio[1215]: info: May 28 22:07:14 volumio volumio[1215]: ---------------------------- MPD announces state update: player May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::getState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand status May 28 22:07:14 volumio volumio[1215]: info: May 28 22:07:14 volumio volumio[1215]: ---------------------------- MPD announces state update: player May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::getState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand status May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand status took 2 milliseconds May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand status took 1 milliseconds May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand status took 2 milliseconds May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseState May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand playlistinfo took 1 milliseconds May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand playlistinfo took 1 milliseconds May 28 22:07:14 volumio volumio[1215]: info: sendMpdCommand playlistinfo took 2 milliseconds May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseTrackInfo May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseTrackInfo May 28 22:07:14 volumio volumio[1215]: verbose: ControllerMpd::parseTrackInfo May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::pushState May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::servicePushState May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"class-flac.flac","artist":"Naim Classical","album":null,"uri":"http://mscp3.live-streams.nl:8250/class-flac.flac","trackType":"flac"} May 28 22:07:14 volumio volumio[1215]: verbose: CURRENT POSITION 0 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState stateService stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState currentStatus stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: No code May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::pushState May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::servicePushState May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"class-flac.flac","artist":"Naim Classical","album":null,"uri":"http://mscp3.live-streams.nl:8250/class-flac.flac","trackType":"flac"} May 28 22:07:14 volumio volumio[1215]: verbose: CURRENT POSITION 0 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState stateService stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState currentStatus stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: No code May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: ControllerMpd::pushState May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::servicePushState May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"class-flac.flac","artist":"Naim Classical","album":null,"uri":"http://mscp3.live-streams.nl:8250/class-flac.flac","trackType":"flac"} May 28 22:07:14 volumio volumio[1215]: verbose: CURRENT POSITION 0 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState stateService stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::syncState currentStatus stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio[1215]: info: No code May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.716+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.716+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.717+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.717+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.718+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.719+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.719+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.719+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.720+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.720+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.721+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.722+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.722+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.722+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.723+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.723+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.724+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=0 volume=52 May 28 22:07:14 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:14.726+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id= title= May 28 22:07:14 volumio volumio[1215]: info: ------------------------------ 74ms May 28 22:07:14 volumio volumio[1215]: info: ------------------------------ 73ms May 28 22:07:14 volumio volumio[1215]: info: ------------------------------ 73ms May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 May 28 22:07:14 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","service":"spop","name":"Gidelim Göksu'ya Bir Âlem i Âb Eyleyelim","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 2","type":"song","duration":232,"albumart":"https://i.scdn.co/image/ab67616d0000b27302c28c5c02286943f1fd4f43","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:14 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::play index 0 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:14 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:4eryUkYCEhJ6Un01D5OfjO in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:1ZY6qlEvWubbmuDkR4Pm5V in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:0yu06ZKa8kBknvB7D7Lo6F in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:5bbDNYXGYrxuJt4UQ5IAAo in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:6LbvBxEMwuNbKoZbTur6NX in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:0cKzCNd6vdaS2XDSxzFlRr in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:53j0CQyPm2kmQ2hQCLzgcx in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:14 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:14 volumio volumio[1215]: info: Exploding uri spotify:track:6cLpQ6E2COriU1MSZSm4i5 in service spop May 28 22:07:14 volumio volumio[1215]: SPOTIFY: EXPLODING URI:spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:14 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:14 volumio volumio[1215]: info: [1779998834907] ControllerSpotify::clearAddPlayTrack May 28 22:07:14 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=debug msg="resolved context of track" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","service":"spop","name":"Tal'atın Devr-i Kamerde Mihri Alem-tab Eder","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 7","type":"song","duration":297,"albumart":"https://i.scdn.co/image/ab67616d0000b2734fd9f16d18da3811c53536ab","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0yu06ZKa8kBknvB7D7Lo6F","service":"spop","name":"Bahçenizde Sünbül Olsam Sevdiğiniz Bir Gül Olsam","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 6","type":"song","duration":287,"albumart":"https://i.scdn.co/image/ab67616d0000b2731e5cbb2a759d27b499ddd324","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:15 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","play_origin":"go-librespot"}} May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1ZY6qlEvWubbmuDkR4Pm5V","service":"spop","name":"Terk Eyledi Gerçi Beni Ol Mah Cemalim","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 11","type":"song","duration":383,"albumart":"https://i.scdn.co/image/ab67616d0000b2735516aa9811e7af731a375af4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6LbvBxEMwuNbKoZbTur6NX","service":"spop","name":"Birlikte Bir Akşam Yine Mey Nûş Edelim Gel - 2","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 2","type":"song","duration":210,"albumart":"https://i.scdn.co/image/ab67616d0000b27302c28c5c02286943f1fd4f43","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo","service":"spop","name":"Sevdiğim Cemâlin Çünki Göremem","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 4","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b2739a805dfa05bc9db58e5fd4ba","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0cKzCNd6vdaS2XDSxzFlRr","service":"spop","name":"Nedir Ol Cünbüş-i Nâdide O Can Sûz Nigâh","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 9","type":"song","duration":246,"albumart":"https://i.scdn.co/image/ab67616d0000b273d08df7445b7d64f31741fd16","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:53j0CQyPm2kmQ2hQCLzgcx","service":"spop","name":"Gördüm Yine Bir Gonca-i Nâdîde Edâyı","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol,3","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273fefd32064b6c78abfe906808","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=debug msg="requested aes key for file 38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274, gid: 0zimaaqW0UrEnGnPIlMufD" May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6cLpQ6E2COriU1MSZSm4i5","service":"spop","name":"Senin Aşkınla Çâk Oldum","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol,1","type":"song","duration":230,"albumart":"https://i.scdn.co/image/ab67616d0000b273122cc7e8071d03d941c260b3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio go-librespot[1605]: time="2026-05-28T22:07:15+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0zimaaqW0UrEnGnPIlMufD: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:15 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:15 volumio volumio[1215]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5bbDNYXGYrxuJt4UQ5IAAo","service":"spop","name":"Ben Seni Sevdim Seveli Kaynayıp Coştum","artist":"Klasik Türk Sanat Müziği Korosu","album":"Museum of Classic Turkish Music Arcieve Vol, 9","type":"song","duration":215,"albumart":"https://i.scdn.co/image/ab67616d0000b273d08df7445b7d64f31741fd16","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 28 22:07:15 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:15 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:15 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:15 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:16 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:16 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:16 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:16 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:16 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:16 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:16 volumio volumio[1215]: info: [1779998836311] ControllerSpotify::clearAddPlayTrack May 28 22:07:16 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:16 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","play_origin":"go-librespot"}} May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=debug msg="requested aes key for file 38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274, gid: 0zimaaqW0UrEnGnPIlMufD" May 28 22:07:16 volumio go-librespot[1605]: time="2026-05-28T22:07:16+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0zimaaqW0UrEnGnPIlMufD: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:16 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:24 volumio volumio[1215]: info: VolumeController::SetAlsaVolume65 May 28 22:07:24 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:24 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 28 22:07:24 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:24 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:24.021+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=7601 volume=65 May 28 22:07:24 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:24.022+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id=spotify:track:0zimaaqW0UrEnGnPIlMufD title="Gidelim Göksu'ya Bir Âlem i Âb Eyleyelim" May 28 22:07:24 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 65 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: SPOTIFY VOLUME 52 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: VOLUMIO VOLUME 65 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: DELTA VOLUME ENOUGH: true May 28 22:07:24 volumio volumio[1215]: info: Setting Spotify Volume from Volumio: 65 May 28 22:07:24 volumio volumio[1215]: info: VolumeController::SetAlsaVolume66 May 28 22:07:24 volumio volumio[1215]: info: CoreStateMachine::pushState May 28 22:07:24 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:24 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 28 22:07:24 volumio volumio[1215]: info: CoreCommandRouter::volumioPushState May 28 22:07:24 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:24.160+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" state=STATUS_STOPPED positionMs=7757 volume=66 May 28 22:07:24 volumio volumio5-onboarding[1815]: time=2026-05-28T22:07:24.160+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.68:45966 @ 0x1ca94a0" id=spotify:track:0zimaaqW0UrEnGnPIlMufD title="Gidelim Göksu'ya Bir Âlem i Âb Eyleyelim" May 28 22:07:24 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: SPOTIFY VOLUME 65 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: VOLUMIO VOLUME 66 May 28 22:07:24 volumio volumio[1215]: SPOTIFY: DELTA VOLUME ENOUGH: false May 28 22:07:25 volumio volumio[1215]: SPOTIFY: SETTING SPOTIFY VOLUME 65 May 28 22:07:25 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/volume May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=debug msg="update volume requested to 42597/65535" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=trace msg="emitting websocket event: volume" May 28 22:07:25 volumio volumio[1215]: SPOTIFY: received: {"type":"volume","data":{"value":65,"max":100}} May 28 22:07:25 volumio volumio[1215]: SPOTIFY: RECEIVED SPOTIFY VOLUME 65 May 28 22:07:25 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:25 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:25 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:25 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:25 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:25 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:25 volumio volumio[1215]: info: [1779998845891] ControllerSpotify::clearAddPlayTrack May 28 22:07:25 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=debug msg="resolved context of track" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:25 volumio go-librespot[1605]: time="2026-05-28T22:07:25+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:25 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","play_origin":"go-librespot"}} May 28 22:07:26 volumio go-librespot[1605]: time="2026-05-28T22:07:26+02:00" level=debug msg="selected format OGG_VORBIS_320 (38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:26 volumio go-librespot[1605]: time="2026-05-28T22:07:26+02:00" level=debug msg="requested aes key for file 38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274, gid: 0zimaaqW0UrEnGnPIlMufD" May 28 22:07:26 volumio go-librespot[1605]: time="2026-05-28T22:07:26+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0zimaaqW0UrEnGnPIlMufD: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:26 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:29 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:29 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:29 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:29 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:29 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:29 volumio volumio[1215]: info: CorePlayQueue::getTrack 0 May 28 22:07:29 volumio volumio[1215]: info: [1779998849373] ControllerSpotify::clearAddPlayTrack May 28 22:07:29 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=debug msg="resolved context of track" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:29 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","uri":"spotify:track:0zimaaqW0UrEnGnPIlMufD","play_origin":"go-librespot"}} May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=debug msg="selected format OGG_VORBIS_320 (38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274)" uri="spotify:track:0zimaaqW0UrEnGnPIlMufD" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=debug msg="requested aes key for file 38acb2d41c14e4fb6e6d822cb1d9cb05f8bf5274, gid: 0zimaaqW0UrEnGnPIlMufD" May 28 22:07:29 volumio go-librespot[1605]: time="2026-05-28T22:07:29+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0zimaaqW0UrEnGnPIlMufD: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:29 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:30 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:30 volumio volumio[1215]: info: CoreCommandRouter::volumioReplaceandPlayItems May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::ClearQueue May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::clearPlayQueue May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:30 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:30 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:30 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:30 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::play index 1 May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:30 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:30 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:30 volumio volumio[1215]: info: Using cached record of: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:30 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:30 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:30 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:30 volumio volumio[1215]: info: [1779998850310] ControllerSpotify::clearAddPlayTrack May 28 22:07:30 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=debug msg="resolved context of track" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:30 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","play_origin":"go-librespot"}} May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=debug msg="selected format OGG_VORBIS_320 (8b4503dc1740c9adcd618ca92389ef95052b869b)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=debug msg="requested aes key for file 8b4503dc1740c9adcd618ca92389ef95052b869b, gid: 4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:30 volumio go-librespot[1605]: time="2026-05-28T22:07:30+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4eryUkYCEhJ6Un01D5OfjO: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:30 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:31 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:31 volumio volumio[1215]: info: CoreCommandRouter::volumioReplaceandPlayItems May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::ClearQueue May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::clearPlayQueue May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:31 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:31 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:0zimaaqW0UrEnGnPIlMufD May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:4eryUkYCEhJ6Un01D5OfjO May 28 22:07:31 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:31 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::play index 1 May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::addQueueItems May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::addQueueItems May 28 22:07:31 volumio volumio[1215]: info: Preload queue cleared May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:1ZY6qlEvWubbmuDkR4Pm5V May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:0yu06ZKa8kBknvB7D7Lo6F May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:5bbDNYXGYrxuJt4UQ5IAAo May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:6LbvBxEMwuNbKoZbTur6NX May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:0EbLgAnnhMrL1AbVMQ2Jqo May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:0cKzCNd6vdaS2XDSxzFlRr May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:53j0CQyPm2kmQ2hQCLzgcx May 28 22:07:31 volumio volumio[1215]: info: Adding Item to queue: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:31 volumio volumio[1215]: info: Using cached record of: spotify:track:6cLpQ6E2COriU1MSZSm4i5 May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:31 volumio volumio[1215]: info: CoreCommandRouter::volumioPushQueue May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::saveQueue May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:31 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:31 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:31 volumio volumio[1215]: info: [1779998851603] ControllerSpotify::clearAddPlayTrack May 28 22:07:31 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=debug msg="resolved context of track" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:31 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","play_origin":"go-librespot"}} May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=debug msg="selected format OGG_VORBIS_320 (8b4503dc1740c9adcd618ca92389ef95052b869b)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=debug msg="requested aes key for file 8b4503dc1740c9adcd618ca92389ef95052b869b, gid: 4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:31 volumio go-librespot[1605]: time="2026-05-28T22:07:31+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4eryUkYCEhJ6Un01D5OfjO: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:31 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:37 volumio volumio[1215]: info: CoreCommandRouter::volumioPlay May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:37 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:37 volumio volumio[1215]: info: CorePlayQueue::getTrack 1 May 28 22:07:37 volumio volumio[1215]: info: [1779998857116] ControllerSpotify::clearAddPlayTrack May 28 22:07:37 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="resolved context of track" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:37 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","uri":"spotify:track:4eryUkYCEhJ6Un01D5OfjO","play_origin":"go-librespot"}} May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="selected format OGG_VORBIS_320 (8b4503dc1740c9adcd618ca92389ef95052b869b)" uri="spotify:track:4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="requested aes key for file 8b4503dc1740c9adcd618ca92389ef95052b869b, gid: 4eryUkYCEhJ6Un01D5OfjO" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4eryUkYCEhJ6Un01D5OfjO: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:37 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:37 volumio volumio[1215]: info: CoreCommandRouter::volumioNext May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::next May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::stop May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::play index undefined May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:07:37 volumio volumio[1215]: info: CorePlayQueue::getTrack 2 May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::startPlaybackTimer May 28 22:07:37 volumio volumio[1215]: info: CorePlayQueue::getTrack 2 May 28 22:07:37 volumio volumio[1215]: info: [1779998857669] ControllerSpotify::clearAddPlayTrack May 28 22:07:37 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/play May 28 22:07:37 volumio volumio[1215]: info: CoreStateMachine::updateTrackBlock May 28 22:07:37 volumio volumio[1215]: info: CorePlayQueue::getTrackBlock May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="resolved context of track" uri="spotify:track:1ZY6qlEvWubbmuDkR4Pm5V" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1ZY6qlEvWubbmuDkR4Pm5V" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1ZY6qlEvWubbmuDkR4Pm5V" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=trace msg="emitting websocket event: will_play" May 28 22:07:37 volumio volumio[1215]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1ZY6qlEvWubbmuDkR4Pm5V","uri":"spotify:track:1ZY6qlEvWubbmuDkR4Pm5V","play_origin":"go-librespot"}} May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="selected format OGG_VORBIS_320 (0ac9a2d041704666127fdcefc29475c39aee34cc)" uri="spotify:track:1ZY6qlEvWubbmuDkR4Pm5V" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=debug msg="requested aes key for file 0ac9a2d041704666127fdcefc29475c39aee34cc, gid: 1ZY6qlEvWubbmuDkR4Pm5V" May 28 22:07:37 volumio go-librespot[1605]: time="2026-05-28T22:07:37+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1ZY6qlEvWubbmuDkR4Pm5V: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:07:37 volumio volumio[1215]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:07:41 volumio ntpd[1040]: CLOCK: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 28 22:07:42 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 28 22:07:42 volumio volumio[1215]: info: In handleBrowseUri, curUri=spotify:artist:0uYjRwVdvJTNh1cGnpFPqI May 28 22:07:42 volumio wpa_supplicant[1180]: wlan0: WPA: Group rekeying completed with 2c:91:ab:59:47:0d [GTK=CCMP] May 28 22:07:43 volumio volumio[1215]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 28 22:07:43 volumio volumio[1215]: TypeError: Cannot read properties of undefined (reading 'url') May 28 22:07:43 volumio volumio[1215]: at /data/plugins/music_service/spop/index.js:2446:60 May 28 22:07:43 volumio volumio[1215]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) May 28 22:07:43 volumio volumio[1215]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 28 22:07:43 volumio sudo[2782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-28 22:06' May 28 22:07:43 volumio sudo[2782]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"