Feb 24 23:37:04 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:04 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:04 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:37:04 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:04 volumio volumio[1413]: info: Adding Item to queue: spotify:album:3VrAUNFdYyCHLAG6T20w2K Feb 24 23:37:04 volumio volumio[1413]: info: Using cached record of: spotify:album:3VrAUNFdYyCHLAG6T20w2K Feb 24 23:37:04 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:37:04 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::play index 0 Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:04 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:37:04 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:04 volumio volumio[1413]: info: [1771943824104] ControllerSpotify::clearAddPlayTrack Feb 24 23:37:04 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=debug msg="resolved context of track" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:37:04 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","play_origin":"go-librespot"}} Feb 24 23:37:04 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","play_origin":"go-librespot"}} Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=debug msg="selected format OGG_VORBIS_320 (610b72d2f5db4433581f41b5631a286422501049)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=debug msg="requested aes key for file 610b72d2f5db4433581f41b5631a286422501049, gid: 0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:04 volumio go-librespot[4392]: time="2026-02-24T23:37:04+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0HGOJNfTI8NgEri18KtyA8: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:37:04 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:37:25 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:25 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:25 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:37:25 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0HGOJNfTI8NgEri18KtyA8 Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:0HGOJNfTI8NgEri18KtyA8 Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:35ltYzEWt6yK94KXzRYvWU Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:35ltYzEWt6yK94KXzRYvWU Feb 24 23:37:25 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:37:25 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::play index 1 Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:37:25 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1D02rBaJMyIKilQ7xe5MX8 Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:1D02rBaJMyIKilQ7xe5MX8 Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4HSaL9oPXtQagb19uutlwm Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:4HSaL9oPXtQagb19uutlwm Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1tPP2UjDEEeRZlEwgoduX3 Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:1tPP2UjDEEeRZlEwgoduX3 Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1T4KJh8OoJWtK4v5B56mEZ Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:1T4KJh8OoJWtK4v5B56mEZ Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:64PUP2iO4amx8gZfcMMrUe Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:64PUP2iO4amx8gZfcMMrUe Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4EfTzzm61oHHfS3DZvQxet Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:4EfTzzm61oHHfS3DZvQxet Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:75w4ANm3lydAA9kbngyHKX Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:75w4ANm3lydAA9kbngyHKX Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:14WmgBsGjfnwdbBCNFStv3 Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:14WmgBsGjfnwdbBCNFStv3 Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3u5n9rwLvvKQPrQAilgbmN Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:3u5n9rwLvvKQPrQAilgbmN Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3uHPdrjogKsdyMiBja4zFg Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:3uHPdrjogKsdyMiBja4zFg Feb 24 23:37:25 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4yw9KLlD8sFJZwH99DgFGs Feb 24 23:37:25 volumio volumio[1413]: info: Using cached record of: spotify:track:4yw9KLlD8sFJZwH99DgFGs Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:25 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::getTrack 1 Feb 24 23:37:25 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:37:25 volumio volumio[1413]: info: CorePlayQueue::getTrack 1 Feb 24 23:37:25 volumio volumio[1413]: info: [1771943845202] ControllerSpotify::clearAddPlayTrack Feb 24 23:37:25 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=debug msg="resolved context of track" uri="spotify:track:35ltYzEWt6yK94KXzRYvWU" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:35ltYzEWt6yK94KXzRYvWU" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:35ltYzEWt6yK94KXzRYvWU" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:37:25 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:35ltYzEWt6yK94KXzRYvWU","uri":"spotify:track:35ltYzEWt6yK94KXzRYvWU","play_origin":"go-librespot"}} Feb 24 23:37:25 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:35ltYzEWt6yK94KXzRYvWU","uri":"spotify:track:35ltYzEWt6yK94KXzRYvWU","play_origin":"go-librespot"}} Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=debug msg="selected format OGG_VORBIS_320 (515a435bccf99d8f64da0de597087d72ad8514bf)" uri="spotify:track:35ltYzEWt6yK94KXzRYvWU" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=debug msg="requested aes key for file 515a435bccf99d8f64da0de597087d72ad8514bf, gid: 35ltYzEWt6yK94KXzRYvWU" Feb 24 23:37:25 volumio go-librespot[4392]: time="2026-02-24T23:37:25+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:35ltYzEWt6yK94KXzRYvWU: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:37:25 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:37:28 volumio go-librespot[4392]: time="2026-02-24T23:37:28+09:00" level=trace msg="sent dealer ping" Feb 24 23:37:29 volumio go-librespot[4392]: time="2026-02-24T23:37:29+09:00" level=trace msg="received dealer pong" Feb 24 23:37:30 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:30 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:30 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:37:30 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:30 volumio volumio[1413]: info: Adding Item to queue: spotify:album:3VrAUNFdYyCHLAG6T20w2K Feb 24 23:37:30 volumio volumio[1413]: info: Using cached record of: spotify:album:3VrAUNFdYyCHLAG6T20w2K Feb 24 23:37:30 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:37:30 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::play index 0 Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:30 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:37:30 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:30 volumio volumio[1413]: info: [1771943850791] ControllerSpotify::clearAddPlayTrack Feb 24 23:37:30 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:37:30 volumio go-librespot[4392]: time="2026-02-24T23:37:30+09:00" level=debug msg="resolved context of track" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:30 volumio go-librespot[4392]: time="2026-02-24T23:37:30+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:30 volumio go-librespot[4392]: time="2026-02-24T23:37:30+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:30 volumio go-librespot[4392]: time="2026-02-24T23:37:30+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:37:30 volumio go-librespot[4392]: time="2026-02-24T23:37:30+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:37:30 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","play_origin":"go-librespot"}} Feb 24 23:37:30 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","uri":"spotify:track:0HGOJNfTI8NgEri18KtyA8","play_origin":"go-librespot"}} Feb 24 23:37:31 volumio go-librespot[4392]: time="2026-02-24T23:37:31+09:00" level=debug msg="selected format OGG_VORBIS_320 (610b72d2f5db4433581f41b5631a286422501049)" uri="spotify:track:0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:31 volumio go-librespot[4392]: time="2026-02-24T23:37:31+09:00" level=debug msg="requested aes key for file 610b72d2f5db4433581f41b5631a286422501049, gid: 0HGOJNfTI8NgEri18KtyA8" Feb 24 23:37:31 volumio go-librespot[4392]: time="2026-02-24T23:37:31+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0HGOJNfTI8NgEri18KtyA8: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:37:31 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:37:37 volumio go-librespot[4392]: time="2026-02-24T23:37:37+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Feb 24 23:37:37 volumio go-librespot[4392]: time="2026-02-24T23:37:37+09:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4on7JxHTbyDi" Feb 24 23:37:37 volumio go-librespot[4392]: time="2026-02-24T23:37:37+09:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1E4BuFespL7Y3A" Feb 24 23:37:37 volumio go-librespot[4392]: time="2026-02-24T23:37:37+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Feb 24 23:37:43 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 24 23:37:43 volumio volumio[1413]: info: In handleBrowseUri, curUri=spotify:album:2uTN1SFpYzj2JCT4oqZmQL Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 24 23:37:45 volumio volumio[1413]: info: Discovery: Getting this device information Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::volumioGetState Feb 24 23:37:45 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 24 23:37:45 volumio volumio[1413]: verbose: New Socket.io Connection to 192.168.0.15:3000 from 192.168.0.4 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 24 23:37:45 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 24 23:37:50 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:50 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:50 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:37:50 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:37:50 volumio volumio[1413]: info: Adding Item to queue: spotify:album:2uTN1SFpYzj2JCT4oqZmQL Feb 24 23:37:50 volumio volumio[1413]: info: Exploding uri spotify:album:2uTN1SFpYzj2JCT4oqZmQL in service spop Feb 24 23:37:50 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:album:2uTN1SFpYzj2JCT4oqZmQL Feb 24 23:37:50 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:37:50 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::play index 0 Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:50 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:37:50 volumio volumio[1413]: info: CorePlayQueue::getTrack 0 Feb 24 23:37:50 volumio volumio[1413]: info: [1771943870539] ControllerSpotify::clearAddPlayTrack Feb 24 23:37:50 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=debug msg="resolved context of track" uri="spotify:track:4bzqxiZ7rQSmJRfJQCZb4W" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4bzqxiZ7rQSmJRfJQCZb4W" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4bzqxiZ7rQSmJRfJQCZb4W" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:37:50 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4bzqxiZ7rQSmJRfJQCZb4W","uri":"spotify:track:4bzqxiZ7rQSmJRfJQCZb4W","play_origin":"go-librespot"}} Feb 24 23:37:50 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4bzqxiZ7rQSmJRfJQCZb4W","uri":"spotify:track:4bzqxiZ7rQSmJRfJQCZb4W","play_origin":"go-librespot"}} Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=debug msg="selected format OGG_VORBIS_320 (d51c5cb3c3df94ead37f3b515ad4fc999d018b6d)" uri="spotify:track:4bzqxiZ7rQSmJRfJQCZb4W" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=debug msg="requested aes key for file d51c5cb3c3df94ead37f3b515ad4fc999d018b6d, gid: 4bzqxiZ7rQSmJRfJQCZb4W" Feb 24 23:37:50 volumio go-librespot[4392]: time="2026-02-24T23:37:50+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4bzqxiZ7rQSmJRfJQCZb4W: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:37:50 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:37:57 volumio go-librespot[4392]: time="2026-02-24T23:37:57+09:00" level=trace msg="received accesspoint ping" Feb 24 23:37:57 volumio go-librespot[4392]: time="2026-02-24T23:37:57+09:00" level=trace msg="received accesspoint pong ack" Feb 24 23:37:58 volumio go-librespot[4392]: time="2026-02-24T23:37:58+09:00" level=trace msg="sent dealer ping" Feb 24 23:37:59 volumio go-librespot[4392]: time="2026-02-24T23:37:59+09:00" level=trace msg="received dealer pong" Feb 24 23:38:01 volumio volumio[1413]: info: [now-playing] Fetching API key... Feb 24 23:38:02 volumio volumio[1413]: error: [now-playing] Caught error in callback of WeatherAPI.#getFetchPromise(): Could not obtain API key Feb 24 23:38:02 volumio volumio[1413]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Could not fetch weather: Could not obtain API key Feb 24 23:38:02 volumio volumio[1413]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:103:19) Feb 24 23:38:02 volumio volumio[1413]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 24 23:38:02 volumio volumio[1413]: at async Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:116:28) Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:4bzqxiZ7rQSmJRfJQCZb4W in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:2gx3HktBszA9o1Af37uzlM in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:3TcwQqNJjwfk4HU3tIQ1fO in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4bzqxiZ7rQSmJRfJQCZb4W","service":"spop","name":"Lute Suite in G Minor, BWV 995: I. Prelude (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":328,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","service":"spop","name":"Lute Suite in G Minor, BWV 995: V. Gavotte I (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":70,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3TcwQqNJjwfk4HU3tIQ1fO","service":"spop","name":"Lute Suite in G Minor, BWV 995: IV. Sarabande (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":108,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1","service":"spop","name":"Lute Suite in G Minor, BWV 995: III. Courante (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":111,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2gx3HktBszA9o1Af37uzlM","service":"spop","name":"Lute Suite in G Minor, BWV 995: II. Allemande (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":169,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::play index 4 Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:71DX9ruHbeeTC7EQQgYA2s in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:3MWGHod8YFC02Suq0QtVlC in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:1VGpeOPFU8A7sCJl6j3Qvq in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6rqToDIwfNnpRCz5xGDsOv in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6lKWcikgQxohp1og3LttdQ in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:22PMrdNtmCr3fi8qa7d3BY in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:7xN5O3nHr84qMrNESSWSCY in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6vfZ6TxBeTcSbG75NgTpUg in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:7DxUWe6GqEiMeFYSasxxRb in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:0VMUMBIlzKrBVGICNY2QTT in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:4jzO25zqPWvCgsqczTjwfT in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6nhq0UjkpdXBZeY1qCA00a in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:5Raou4mW3DH26DlYNo3I87 in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:5O4QOaocunbrZzF2gmDdwb in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:4pGwjYXefQs097cDBVwSWk in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:2jMCz39zc5sPJlIAVAnauV in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:08 volumio volumio[1413]: info: [1771943888779] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:08 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:08 volumio volumio[1413]: info: Using cached record of: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:08 volumio volumio[1413]: info: Using cached record of: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:08 volumio volumio[1413]: info: Using cached record of: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:08 volumio volumio[1413]: info: Using cached record of: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:08 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::play index 3 Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:08 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:08 volumio volumio[1413]: info: Using cached record of: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:71DX9ruHbeeTC7EQQgYA2s in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:3MWGHod8YFC02Suq0QtVlC in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:1VGpeOPFU8A7sCJl6j3Qvq in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6rqToDIwfNnpRCz5xGDsOv in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6lKWcikgQxohp1og3LttdQ in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:22PMrdNtmCr3fi8qa7d3BY in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:7xN5O3nHr84qMrNESSWSCY in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6vfZ6TxBeTcSbG75NgTpUg in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:7DxUWe6GqEiMeFYSasxxRb in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:0VMUMBIlzKrBVGICNY2QTT in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:4jzO25zqPWvCgsqczTjwfT in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:6nhq0UjkpdXBZeY1qCA00a in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:5Raou4mW3DH26DlYNo3I87 in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:5O4QOaocunbrZzF2gmDdwb in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:4pGwjYXefQs097cDBVwSWk in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:08 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:08 volumio volumio[1413]: info: Exploding uri spotify:track:2jMCz39zc5sPJlIAVAnauV in service spop Feb 24 23:38:08 volumio volumio[1413]: SPOTIFY: EXPLODING URI:spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrack 3 Feb 24 23:38:08 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:08 volumio volumio[1413]: info: CorePlayQueue::getTrack 3 Feb 24 23:38:08 volumio volumio[1413]: info: [1771943888848] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:08 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:08 volumio go-librespot[4392]: time="2026-02-24T23:38:08+09:00" level=debug msg="resolved context of track" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:08 volumio go-librespot[4392]: time="2026-02-24T23:38:08+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:08 volumio go-librespot[4392]: time="2026-02-24T23:38:08+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="selected format OGG_VORBIS_320 (26aaca4a7bf84bc52fe440d151805bd6452f88f6)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="requested aes key for file 26aaca4a7bf84bc52fe440d151805bd6452f88f6, gid: 2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2AZONBpKQyYlZTQ6Iuj2e0: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="resolved context of track" uri="spotify:track:3TcwQqNJjwfk4HU3tIQ1fO" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3TcwQqNJjwfk4HU3tIQ1fO" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3TcwQqNJjwfk4HU3tIQ1fO" Feb 24 23:38:09 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:22PMrdNtmCr3fi8qa7d3BY","service":"spop","name":"Lute Suite in E Minor, BWV 996: IV. Sarabande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":280,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7DxUWe6GqEiMeFYSasxxRb","service":"spop","name":"Lute Partita in C Minor, BWV 997: I. Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":262,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3MWGHod8YFC02Suq0QtVlC","service":"spop","name":"Lute Suite in G Minor, BWV 995: VII. Gigue (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":82,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6nhq0UjkpdXBZeY1qCA00a","service":"spop","name":"Lute Partita in C Minor, BWV 997: IV. Gigue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":149,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6lKWcikgQxohp1og3LttdQ","service":"spop","name":"Lute Suite in E Minor, BWV 996: III. Courante (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":123,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1VGpeOPFU8A7sCJl6j3Qvq","service":"spop","name":"Lute Suite in E Minor, BWV 996: I. Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":143,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1VGpeOPFU8A7sCJl6j3Qvq","service":"spop","name":"Lute Suite in E Minor, BWV 996: I. Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":143,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:71DX9ruHbeeTC7EQQgYA2s","service":"spop","name":"Lute Suite in G Minor, BWV 995: VI. Gavotte II en rondeau (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":92,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6rqToDIwfNnpRCz5xGDsOv","service":"spop","name":"Lute Suite in E Minor, BWV 996: II. Allemande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":143,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:71DX9ruHbeeTC7EQQgYA2s","service":"spop","name":"Lute Suite in G Minor, BWV 995: VI. Gavotte II en rondeau (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":92,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vfZ6TxBeTcSbG75NgTpUg","service":"spop","name":"Lute Suite in E Minor, BWV 996: VI. Gigue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":95,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4pGwjYXefQs097cDBVwSWk","service":"spop","name":"Prelude, Fugue and Allegro in E-Flat Major, BWV 998: Fugue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":317,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3MWGHod8YFC02Suq0QtVlC","service":"spop","name":"Lute Suite in G Minor, BWV 995: VII. Gigue (Arr. P. Gabrailth)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":82,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0VMUMBIlzKrBVGICNY2QTT","service":"spop","name":"Lute Partita in C Minor, BWV 997: II. Fugue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":399,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6lKWcikgQxohp1og3LttdQ","service":"spop","name":"Lute Suite in E Minor, BWV 996: III. Courante (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":123,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Raou4mW3DH26DlYNo3I87","service":"spop","name":"Lute Partita in C Minor, BWV 997: V. Double (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":119,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5O4QOaocunbrZzF2gmDdwb","service":"spop","name":"Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":117,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6rqToDIwfNnpRCz5xGDsOv","service":"spop","name":"Lute Suite in E Minor, BWV 996: II. Allemande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":143,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7xN5O3nHr84qMrNESSWSCY","service":"spop","name":"Lute Suite in E Minor, BWV 996: V. Bourree (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":48,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0VMUMBIlzKrBVGICNY2QTT","service":"spop","name":"Lute Partita in C Minor, BWV 997: II. Fugue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":399,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7DxUWe6GqEiMeFYSasxxRb","service":"spop","name":"Lute Partita in C Minor, BWV 997: I. Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":262,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vfZ6TxBeTcSbG75NgTpUg","service":"spop","name":"Lute Suite in E Minor, BWV 996: VI. Gigue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":95,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4jzO25zqPWvCgsqczTjwfT","service":"spop","name":"Lute Partita in C Minor, BWV 997: III. Sarabande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2jMCz39zc5sPJlIAVAnauV","service":"spop","name":"Prelude, Fugue and Allegro in E-Flat Major, BWV 998: Allegro (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":144,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:09 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:09 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:09 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7xN5O3nHr84qMrNESSWSCY","service":"spop","name":"Lute Suite in E Minor, BWV 996: V. Bourree (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":48,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5O4QOaocunbrZzF2gmDdwb","service":"spop","name":"Prelude (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":117,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Raou4mW3DH26DlYNo3I87","service":"spop","name":"Lute Partita in C Minor, BWV 997: V. Double (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":119,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3TcwQqNJjwfk4HU3tIQ1fO","uri":"spotify:track:3TcwQqNJjwfk4HU3tIQ1fO","play_origin":"go-librespot"}} Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3TcwQqNJjwfk4HU3tIQ1fO","uri":"spotify:track:3TcwQqNJjwfk4HU3tIQ1fO","play_origin":"go-librespot"}} Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4pGwjYXefQs097cDBVwSWk","service":"spop","name":"Prelude, Fugue and Allegro in E-Flat Major, BWV 998: Fugue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":317,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4jzO25zqPWvCgsqczTjwfT","service":"spop","name":"Lute Partita in C Minor, BWV 997: III. Sarabande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6nhq0UjkpdXBZeY1qCA00a","service":"spop","name":"Lute Partita in C Minor, BWV 997: IV. Gigue (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":149,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2jMCz39zc5sPJlIAVAnauV","service":"spop","name":"Prelude, Fugue and Allegro in E-Flat Major, BWV 998: Allegro (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":144,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:22PMrdNtmCr3fi8qa7d3BY","service":"spop","name":"Lute Suite in E Minor, BWV 996: IV. Sarabande (Arr. P. Galbraith)","artist":"Johann Sebastian Bach","album":"Bach, J.S.: Lute Music (Arr. for Guitar)","type":"song","duration":280,"albumart":"https://i.scdn.co/image/ab67616d0000b273dbb1041e4f01f3b6f4f14026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 24 23:38:09 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="selected format OGG_VORBIS_320 (0870d5f93050b9be141d32920c0e6693d3ee8f25)" uri="spotify:track:3TcwQqNJjwfk4HU3tIQ1fO" Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=debug msg="requested aes key for file 0870d5f93050b9be141d32920c0e6693d3ee8f25, gid: 3TcwQqNJjwfk4HU3tIQ1fO" Feb 24 23:38:09 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:09 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:09 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:09 volumio go-librespot[4392]: time="2026-02-24T23:38:09+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3TcwQqNJjwfk4HU3tIQ1fO: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:09 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:10 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:10 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:10 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:10 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:10 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:10 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::play index 4 Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:10 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:10 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:10 volumio volumio[1413]: info: Using cached record of: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:10 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:10 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:10 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:10 volumio volumio[1413]: info: [1771943890358] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:10 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=debug msg="resolved context of track" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:10 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:10 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=debug msg="selected format OGG_VORBIS_320 (26aaca4a7bf84bc52fe440d151805bd6452f88f6)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=debug msg="requested aes key for file 26aaca4a7bf84bc52fe440d151805bd6452f88f6, gid: 2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:10 volumio go-librespot[4392]: time="2026-02-24T23:38:10+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2AZONBpKQyYlZTQ6Iuj2e0: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:10 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: [1771943891281] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:11 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="resolved context of track" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:11 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:11 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: [1771943891504] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:11 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="selected format OGG_VORBIS_320 (26aaca4a7bf84bc52fe440d151805bd6452f88f6)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="requested aes key for file 26aaca4a7bf84bc52fe440d151805bd6452f88f6, gid: 2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2AZONBpKQyYlZTQ6Iuj2e0: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:11 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::ClearQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::clearPlayQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="resolved context of track" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4bzqxiZ7rQSmJRfJQCZb4W Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2gx3HktBszA9o1Af37uzlM Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Ejd7Mx4TvAMeB4FHKxSa1 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3TcwQqNJjwfk4HU3tIQ1fO Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2AZONBpKQyYlZTQ6Iuj2e0 Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPlay Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::addQueueItems Feb 24 23:38:11 volumio volumio[1413]: info: Preload queue cleared Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:71DX9ruHbeeTC7EQQgYA2s Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:3MWGHod8YFC02Suq0QtVlC Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:1VGpeOPFU8A7sCJl6j3Qvq Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6rqToDIwfNnpRCz5xGDsOv Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6lKWcikgQxohp1og3LttdQ Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:22PMrdNtmCr3fi8qa7d3BY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7xN5O3nHr84qMrNESSWSCY Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6vfZ6TxBeTcSbG75NgTpUg Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:7DxUWe6GqEiMeFYSasxxRb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:0VMUMBIlzKrBVGICNY2QTT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4jzO25zqPWvCgsqczTjwfT Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:6nhq0UjkpdXBZeY1qCA00a Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5Raou4mW3DH26DlYNo3I87 Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:5O4QOaocunbrZzF2gmDdwb Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:4pGwjYXefQs097cDBVwSWk Feb 24 23:38:11 volumio volumio[1413]: info: Adding Item to queue: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: Using cached record of: spotify:track:2jMCz39zc5sPJlIAVAnauV Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::stop Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreCommandRouter::volumioPushQueue Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::saveQueue Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::play index undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::updateTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrackBlock Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: CoreStateMachine::startPlaybackTimer Feb 24 23:38:11 volumio volumio[1413]: info: CorePlayQueue::getTrack 4 Feb 24 23:38:11 volumio volumio[1413]: info: [1771943891687] ControllerSpotify::clearAddPlayTrack Feb 24 23:38:11 volumio volumio[1413]: info: Sending Spotify command with payload to local API: /player/play Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:11 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:11 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="selected format OGG_VORBIS_320 (26aaca4a7bf84bc52fe440d151805bd6452f88f6)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=debug msg="requested aes key for file 26aaca4a7bf84bc52fe440d151805bd6452f88f6, gid: 2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:11 volumio go-librespot[4392]: time="2026-02-24T23:38:11+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2AZONBpKQyYlZTQ6Iuj2e0: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:11 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=debug msg="resolved context of track" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=trace msg="emitting websocket event: will_play" Feb 24 23:38:12 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:12 volumio volumio[1413]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","uri":"spotify:track:2AZONBpKQyYlZTQ6Iuj2e0","play_origin":"go-librespot"}} Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=debug msg="selected format OGG_VORBIS_320 (26aaca4a7bf84bc52fe440d151805bd6452f88f6)" uri="spotify:track:2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=debug msg="requested aes key for file 26aaca4a7bf84bc52fe440d151805bd6452f88f6, gid: 2AZONBpKQyYlZTQ6Iuj2e0" Feb 24 23:38:12 volumio go-librespot[4392]: time="2026-02-24T23:38:12+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2AZONBpKQyYlZTQ6Iuj2e0: failed retrieving audio key: failed retrieving aes key with code 1" Feb 24 23:38:12 volumio volumio[1413]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 24 23:38:23 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 24 23:38:23 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 24 23:38:23 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 24 23:38:25 volumio volumio[1413]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 24 23:38:25 volumio volumio[1413]: info: In handleBrowseUri, curUri=spotify:album:29yHIIfH0wZQ3lj9CuIC6a Feb 24 23:38:25 volumio volumio[1413]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:38:25 volumio volumio[1413]: TypeError: Cannot read properties of undefined (reading 'url') Feb 24 23:38:25 volumio volumio[1413]: at /data/plugins/music_service/spop/index.js:2480:69 Feb 24 23:38:25 volumio volumio[1413]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 24 23:38:25 volumio volumio[1413]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 23:38:26 volumio sudo[4679]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-24 23:37' Feb 24 23:38:26 volumio sudo[4679]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"