-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sun 2025-09-14 20:52:49 CEST. -- Sep 14 20:51:07 volumio volumio[991]: info: CoreCommandRouter::volumioGetVisibleSources Sep 14 20:51:07 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 20:51:09 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:51:09 volumio volumio[991]: info: CURURI: playlists Sep 14 20:51:09 volumio volumio[991]: info: Listing playlists Sep 14 20:51:09 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:10 volumio go-librespot[20696]: time="2025-09-14T20:51:10+02:00" level=trace msg="sent dealer ping" Sep 14 20:51:10 volumio go-librespot[20696]: time="2025-09-14T20:51:10+02:00" level=trace msg="received dealer pong" Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 14 20:51:11 volumio volumio[991]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Sep 14 20:51:11 volumio volumio[991]: info: Received Get System Version Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 14 20:51:11 volumio volumio[991]: info: Received Get System Info Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:51:11 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:51:11 volumio volumio[991]: info: CorePlayQueue::getTrack 32 Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:51:11 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:51:11 volumio volumio[991]: info: CURURI: playlists/Ptoszki Sep 14 20:51:11 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:11 volumio volumio[991]: info: Preloading song: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:11 volumio volumio[991]: info: Exploding uri spotify:track:0GC8vCFKNHjC2myLf1o8v2 in service spop Sep 14 20:51:11 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:11 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0GC8vCFKNHjC2myLf1o8v2","service":"spop","name":"Forest Bird","artist":"Epic Soundscapes","album":"Epic Birds - vol.1","type":"song","duration":182,"albumart":"https://i.scdn.co/image/ab67616d0000b2734dcb149b2d30cb85d1a1430c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:13 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::ClearQueue Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::stPlaybackTimer Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::pushState Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrack 32 Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::volumioPushState Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::serviceStop Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrack 32 Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::serviceStop Sep 14 20:51:13 volumio volumio[991]: info: Spotify Stop Sep 14 20:51:13 volumio volumio[991]: SPOTIFY: SPOTIFY STOP Sep 14 20:51:13 volumio volumio[991]: SPOTIFY: {"status":"pause","title":"Forest Bird","artist":"Epic Soundscapes","album":"Epic Birds - vol.1","albumart":"https://i.scdn.co/image/ab67616d00001e024dcb149b2d30cb85d1a1430c","uri":"spotify:track:0GC8vCFKNHjC2myLf1o8v2","trackType":"spotify","codec":"ogg","seek":60000,"duration":182,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":true,"repeat":true,"repeatSingle":true,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Sep 14 20:51:13 volumio volumio[991]: info: Sending Spotify command to local API: /player/pause Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::clearPlayQueue Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:13 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:13 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:13 volumio volumio[991]: info: Using cached record of: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:13 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::play index 0 Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrack 0 Sep 14 20:51:13 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:13 volumio volumio[991]: info: CorePlayQueue::getTrack 0 Sep 14 20:51:13 volumio volumio[991]: info: [1757875873412] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:13 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:13 volumio volumio[991]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=debug msg="resolved context of track" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:51:13 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0GC8vCFKNHjC2myLf1o8v2","play_origin":"go-librespot"}} Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=debug msg="selected format OGG_VORBIS_320 (4a0204f72764d111506d7073da299ab0578581b0)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+02:00" level=debug msg="requested aes key for file 4a0204f72764d111506d7073da299ab0578581b0, gid: 0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:13 volumio go-librespot[20696]: time="2025-09-14T20:51:13+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:0GC8vCFKNHjC2myLf1o8v2: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:51:13 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:51:16 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:51:16 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:51:16 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:51:16 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:51:16 volumio volumio[991]: info: CorePlayQueue::getTrack 0 Sep 14 20:51:16 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:51:16 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:16 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:16 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:16 volumio volumio[991]: info: CorePlayQueue::getTrack 0 Sep 14 20:51:16 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:16 volumio volumio[991]: info: CorePlayQueue::getTrack 0 Sep 14 20:51:16 volumio volumio[991]: info: [1757875876884] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:16 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:16 volumio go-librespot[20696]: time="2025-09-14T20:51:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:16 volumio go-librespot[20696]: time="2025-09-14T20:51:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:16 volumio go-librespot[20696]: time="2025-09-14T20:51:16+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:16 volumio go-librespot[20696]: time="2025-09-14T20:51:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:51:16 volumio go-librespot[20696]: time="2025-09-14T20:51:16+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:51:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0GC8vCFKNHjC2myLf1o8v2","play_origin":"go-librespot"}} Sep 14 20:51:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0GC8vCFKNHjC2myLf1o8v2","play_origin":"go-librespot"}} Sep 14 20:51:17 volumio go-librespot[20696]: time="2025-09-14T20:51:17+02:00" level=debug msg="selected format OGG_VORBIS_320 (4a0204f72764d111506d7073da299ab0578581b0)" uri="spotify:track:0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:17 volumio go-librespot[20696]: time="2025-09-14T20:51:17+02:00" level=debug msg="requested aes key for file 4a0204f72764d111506d7073da299ab0578581b0, gid: 0GC8vCFKNHjC2myLf1o8v2" Sep 14 20:51:17 volumio go-librespot[20696]: time="2025-09-14T20:51:17+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:0GC8vCFKNHjC2myLf1o8v2: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:51:17 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:51:21 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:21 volumio volumio[991]: info: Preloading song: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:21 volumio volumio[991]: info: Exploding uri spotify:track:3NfxSdJnVdon1axzloJgba in service spop Sep 14 20:51:21 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:21 volumio volumio[991]: info: Exploding uri spotify:track:2FTO3XZkp89p0CgbGYzwZf in service spop Sep 14 20:51:21 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:21 volumio volumio[991]: info: Exploding uri spotify:track:2BWzjuHLovmZgqGKB4bauX in service spop Sep 14 20:51:21 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:22 volumio volumio[991]: info: Exploding uri spotify:track:0dorKIz071s55Jy0zxb4aW in service spop Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2FTO3XZkp89p0CgbGYzwZf","service":"spop","name":"Heads Up","artist":"Ori Kul","album":"Heads Up","type":"song","duration":144,"albumart":"https://i.scdn.co/image/ab67616d0000b27372d9eb4b1f67002e2e3072c2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: info: Exploding uri spotify:track:4jAa98YFmgJOA0XBLxm6YN in service spop Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","service":"spop","name":"Everloving","artist":"Moby","album":"Play & Play: B Sides","type":"song","duration":205,"albumart":"https://i.scdn.co/image/ab67616d0000b2734964b63a3b440fa58bb9d09e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3NfxSdJnVdon1axzloJgba","service":"spop","name":"I Say a Little Prayer","artist":"Aretha Franklin","album":"Aretha Now","type":"song","duration":216,"albumart":"https://i.scdn.co/image/ab67616d0000b27346c31f64babcbfca6e061b6b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: info: Exploding uri spotify:track:3rb0tMq42WfggucPm0HHkA in service spop Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0dorKIz071s55Jy0zxb4aW","service":"spop","name":"Złote Tarasy","artist":"Mr. Polska","album":"Złote Tarasy","type":"song","duration":146,"albumart":"https://i.scdn.co/image/ab67616d0000b27355f2ab38bba095bb339863b2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: info: Exploding uri spotify:track:0GRc3eGTg8HBdWLRGYgqIc in service spop Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4jAa98YFmgJOA0XBLxm6YN","service":"spop","name":"Femme Like U","artist":"Monaldin","album":"Femme Like U","type":"song","duration":137,"albumart":"https://i.scdn.co/image/ab67616d0000b273aeaaf865251438ab22ded556","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: info: Exploding uri spotify:track:6vl9YrKGyjtkVhYLJNPidM in service spop Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: EXPLODING URI:spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0GRc3eGTg8HBdWLRGYgqIc","service":"spop","name":"Azizam","artist":"Ed Sheeran","album":"Azizam","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b273d29a003b6e8d4c1c47bd4da4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3rb0tMq42WfggucPm0HHkA","service":"spop","name":"Bad Memories (feat. Elley Duhé & FAST BOY)","artist":"MEDUZA","album":"Bad Memories (feat. Elley Duhé & FAST BOY)","type":"song","duration":148,"albumart":"https://i.scdn.co/image/ab67616d0000b27320abd13bf81d8ee406827c38","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vl9YrKGyjtkVhYLJNPidM","service":"spop","name":"L'autre valse d'Amélie - Quatuor à cordes et piano","artist":"Yann Tiersen","album":"Le Fabuleux destin d'Amélie Poulain (Bande originale du film)","type":"song","duration":101,"albumart":"https://i.scdn.co/image/ab67616d0000b2731b7844a8c73c4d48f0bca1de","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:51:29 volumio volumio[991]: info: CoreCommandRouter::volumioStop Sep 14 20:51:29 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:29 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:32 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:32 volumio volumio[991]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::ClearQueue Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::clearPlayQueue Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:32 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:32 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:32 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:32 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::play index 2 Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:32 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:32 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:32 volumio volumio[991]: info: Using cached record of: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:32 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:32 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:32 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:32 volumio volumio[991]: info: [1757875892218] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:32 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:51:33 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:51:33 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:51:33 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:33 volumio volumio[991]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::ClearQueue Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::clearPlayQueue Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:33 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:33 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:33 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:33 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::play index 2 Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:33 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:33 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:33 volumio volumio[991]: info: Using cached record of: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:33 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:33 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:33 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:33 volumio volumio[991]: info: [1757875893864] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:33 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:33 volumio go-librespot[20696]: time="2025-09-14T20:51:33+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:51:34 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:34 volumio volumio[991]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::ClearQueue Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::clearPlayQueue Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:34 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:34 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:3NfxSdJnVdon1axzloJgba Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:2FTO3XZkp89p0CgbGYzwZf Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:2BWzjuHLovmZgqGKB4bauX Sep 14 20:51:34 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:34 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::play index 2 Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::addQueueItems Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::addQueueItems Sep 14 20:51:34 volumio volumio[991]: info: Preload queue cleared Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:0dorKIz071s55Jy0zxb4aW Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:4jAa98YFmgJOA0XBLxm6YN Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:3rb0tMq42WfggucPm0HHkA Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:0GRc3eGTg8HBdWLRGYgqIc Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:6vl9YrKGyjtkVhYLJNPidM Sep 14 20:51:34 volumio volumio[991]: info: Adding Item to queue: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:34 volumio volumio[991]: info: Using cached record of: spotify:track:0GC8vCFKNHjC2myLf1o8v2 Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:34 volumio volumio[991]: info: CoreCommandRouter::volumioPushQueue Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::saveQueue Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::updateTrackBlock Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::getTrackBlock Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:34 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:34 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:34 volumio volumio[991]: info: [1757875894617] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:34 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:35 volumio go-librespot[20696]: time="2025-09-14T20:51:35+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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:51:35 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:51:40 volumio go-librespot[20696]: time="2025-09-14T20:51:40+02:00" level=trace msg="sent dealer ping" Sep 14 20:51:40 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 14 20:51:40 volumio volumio[991]: info: Received Get System Info Sep 14 20:51:40 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:51:40 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:51:40 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:51:40 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:51:40 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:40 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:51:40 volumio go-librespot[20696]: time="2025-09-14T20:51:40+02:00" level=trace msg="received dealer pong" Sep 14 20:51:41 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 14 20:51:41 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 14 20:51:45 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:45 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:45 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:45 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:45 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:45 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:45 volumio volumio[991]: info: [1757875905042] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:45 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:51:46 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:51:46 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:51:46 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:51:46 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:51:46 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:46 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:51:51 volumio volumio[991]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 14 20:51:58 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:51:58 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:51:58 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:51:58 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:58 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:51:58 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:51:58 volumio volumio[991]: info: [1757875918242] ControllerSpotify::clearAddPlayTrack Sep 14 20:51:58 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:52:00 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:52:00 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:52:00 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:52:00 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:00 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:52:00 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:00 volumio volumio[991]: info: [1757875920952] ControllerSpotify::clearAddPlayTrack Sep 14 20:52:00 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:52:10 volumio go-librespot[20696]: time="2025-09-14T20:52:10+02:00" level=trace msg="received accesspoint ping" Sep 14 20:52:10 volumio go-librespot[20696]: time="2025-09-14T20:52:10+02:00" level=trace msg="received accesspoint pong ack" Sep 14 20:52:10 volumio go-librespot[20696]: time="2025-09-14T20:52:10+02:00" level=trace msg="sent dealer ping" Sep 14 20:52:10 volumio go-librespot[20696]: time="2025-09-14T20:52:10+02:00" level=trace msg="received dealer pong" Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:52:15 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:15 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:52:15 volumio volumio[991]: verbose: New Socket.io Connection to 192.168.50.80:3000 from 192.168.50.225 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 11 Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:15 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 14 20:52:15 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:15 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52: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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:15 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:15 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:15 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52:15+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:15 volumio go-librespot[20696]: time="2025-09-14T20:52: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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:15 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52: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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:16 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52: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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:16 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:16 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52:16+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:16 volumio go-librespot[20696]: time="2025-09-14T20:52: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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:16 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:16 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:16 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:17 volumio sudo[21660]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 14 20:52:17 volumio sudo[21660]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 20:52:17 volumio sudo[21660]: pam_unix(sudo:session): session closed for user root Sep 14 20:52:17 volumio sudo[21663]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 14 20:52:17 volumio sudo[21663]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 20:52:17 volumio sudo[21663]: pam_unix(sudo:session): session closed for user root Sep 14 20:52:17 volumio volumio[991]: verbose: New Socket.io Connection to 192.168.50.80 from 192.168.50.225 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_6_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::volumioGetVisibleSources Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:17 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 14 20:52:17 volumio sudo[21666]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 14 20:52:17 volumio sudo[21666]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 20:52:17 volumio sudo[21666]: pam_unix(sudo:session): session closed for user root Sep 14 20:52:17 volumio sudo[21669]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 14 20:52:17 volumio sudo[21669]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 20:52:17 volumio sudo[21669]: pam_unix(sudo:session): session closed for user root Sep 14 20:52:17 volumio volumio[991]: verbose: New Socket.io Connection to 192.168.50.80 from 192.168.50.225 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_6_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:17 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 14 20:52:17 volumio volumio[991]: info: Listing playlists Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 14 20:52:17 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 14 20:52:18 volumio volumio[991]: info: VolumeController::SetAlsaVolume109 Sep 14 20:52:18 volumio volumio[991]: info: CoreStateMachine::pushState Sep 14 20:52:18 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::volumioPushState Sep 14 20:52:18 volumio volumio[991]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 14 20:52:18 volumio volumio[991]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'HDMI',0 Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:52:18 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:18 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:18 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:52:21 volumio volumio[991]: info: Adding spotify:track:2BWzjuHLovmZgqGKB4bauX to favourites using generic method Sep 14 20:52:21 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: spop , getTrack Sep 14 20:52:22 volumio volumio[991]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","service":"spop","name":"Everloving","artist":"Moby","album":"Play & Play: B Sides","type":"song","duration":205,"albumart":"https://i.scdn.co/image/ab67616d0000b2734964b63a3b440fa58bb9d09e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 14 20:52:22 volumio volumio[991]: info: Saving local item favourites Sep 14 20:52:22 volumio volumio[991]: info: Pushing Favourites {"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","favourite":true} Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::volumioGetVisibleSources Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::volumioGetQueue Sep 14 20:52:24 volumio volumio[991]: info: CoreStateMachine::getQueue Sep 14 20:52:24 volumio volumio[991]: info: CorePlayQueue::getQueue Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::volumioSeek Sep 14 20:52:24 volumio volumio[991]: info: CoreStateMachine::seek Sep 14 20:52:24 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:24 volumio volumio[991]: info: TRACKBLOCK {"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","service":"spop","name":"Everloving","artist":"Moby","album":"Play & Play: B Sides","type":"song","duration":205,"albumart":"https://i.scdn.co/image/ab67616d0000b2734964b63a3b440fa58bb9d09e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"} Sep 14 20:52:24 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:52:24 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:24 volumio volumio[991]: info: Spotify seek to: 68000 Sep 14 20:52:24 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/seek Sep 14 20:52:24 volumio volumio[991]: info: CoreStateMachine::pushState Sep 14 20:52:24 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 14 20:52:24 volumio volumio[991]: info: CoreCommandRouter::volumioPushState Sep 14 20:52:24 volumio volumio[991]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 14 20:52:26 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:26 volumio volumio[991]: info: CURURI: music-library Sep 14 20:52:26 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:28 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:28 volumio volumio[991]: info: CURURI: music-library/INTERNAL Sep 14 20:52:28 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:30 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:30 volumio volumio[991]: info: CURURI: music-library/INTERNAL/NowPlayingPlugin Sep 14 20:52:30 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:31 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:31 volumio volumio[991]: info: CURURI: music-library/INTERNAL/NowPlayingPlugin/My Backgrounds Sep 14 20:52:31 volumio volumio[991]: error: Failed LSINFO: null Sep 14 20:52:31 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:35 volumio volumio[991]: info: CURURI: music-library/NAS Sep 14 20:52:35 volumio volumio[991]: error: Failed LSINFO: null Sep 14 20:52:35 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 14 20:52:35 volumio volumio[991]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Sep 14 20:52:35 volumio volumio[991]: info: Received Get System Version Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 14 20:52:35 volumio volumio[991]: info: Received Get System Info Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:52:35 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:35 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:35 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:52:36 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:36 volumio volumio[991]: info: CURURI: music-library/USB Sep 14 20:52:36 volumio volumio[991]: error: Failed LSINFO: null Sep 14 20:52:36 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:38 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 14 20:52:38 volumio volumio[991]: info: CURURI: music-library/INTERNAL Sep 14 20:52:38 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:40 volumio go-librespot[20696]: time="2025-09-14T20:52:40+02:00" level=trace msg="sent dealer ping" Sep 14 20:52:40 volumio go-librespot[20696]: time="2025-09-14T20:52:40+02:00" level=trace msg="received dealer pong" Sep 14 20:52:43 volumio volumio[991]: info: CoreCommandRouter::volumioStop Sep 14 20:52:43 volumio volumio[991]: info: CoreStateMachine::stop Sep 14 20:52:43 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:52:43 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 14 20:52:43 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 20:52:43 volumio volumio[991]: info: Discovery: Getting this device information Sep 14 20:52:43 volumio volumio[991]: info: CoreCommandRouter::volumioGetState Sep 14 20:52:43 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:43 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 20:52:44 volumio volumio[991]: info: CoreCommandRouter::volumioPlay Sep 14 20:52:44 volumio volumio[991]: info: CoreStateMachine::play index undefined Sep 14 20:52:44 volumio volumio[991]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 14 20:52:44 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:44 volumio volumio[991]: info: CoreStateMachine::startPlaybackTimer Sep 14 20:52:44 volumio volumio[991]: info: CorePlayQueue::getTrack 2 Sep 14 20:52:44 volumio volumio[991]: info: [1757875964353] ControllerSpotify::clearAddPlayTrack Sep 14 20:52:44 volumio volumio[991]: info: Sending Spotify command with payload to local API: /player/play Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=debug msg="resolved context of track" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 20:52:44 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:44 volumio volumio[991]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2BWzjuHLovmZgqGKB4bauX","play_origin":"go-librespot"}} Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=debug msg="selected format OGG_VORBIS_320 (ba07018b394d1bdb81ce077157d2a4b44c6e0877)" uri="spotify:track:2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+02:00" level=debug msg="requested aes key for file ba07018b394d1bdb81ce077157d2a4b44c6e0877, gid: 2BWzjuHLovmZgqGKB4bauX" Sep 14 20:52:44 volumio go-librespot[20696]: time="2025-09-14T20:52:44+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:2BWzjuHLovmZgqGKB4bauX: failed retrieving audio key: failed retrieving aes key with code 1" Sep 14 20:52:44 volumio volumio[991]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 14 20:52:44 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 14 20:52:44 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:46 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 14 20:52:47 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:48 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 14 20:52:48 volumio volumio[991]: info: Preload queue cleared Sep 14 20:52:49 volumio volumio[991]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 14 20:52:49 volumio volumio[991]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 14 20:52:49 volumio volumio[991]: TypeError: Cannot read property 'length' of undefined Sep 14 20:52:49 volumio volumio[991]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Sep 14 20:52:49 volumio volumio[991]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Sep 14 20:52:49 volumio volumio[991]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Sep 14 20:52:49 volumio volumio[991]: at Parser.emit (events.js:315:20) Sep 14 20:52:49 volumio volumio[991]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Sep 14 20:52:49 volumio volumio[991]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Sep 14 20:52:49 volumio volumio[991]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Sep 14 20:52:49 volumio volumio[991]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Sep 14 20:52:49 volumio volumio[991]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Sep 14 20:52:49 volumio volumio[991]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Sep 14 20:52:49 volumio volumio[991]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Sep 14 20:52:49 volumio volumio[991]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Sep 14 20:52:49 volumio volumio[991]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Sep 14 20:52:49 volumio volumio[991]: at IncomingMessage.emit (events.js:327:22) Sep 14 20:52:49 volumio volumio[991]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 14 20:52:49 volumio volumio[991]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 14 20:52:49 volumio volumio[991]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 14 20:52:49 volumio sudo[21786]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-14 20:51 Sep 14 20:52:49 volumio sudo[21786]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"