-- Logs begin at Sat 2025-11-01 08:15:30 -03, end at Sat 2025-11-01 08:34:09 -03. -- Nov 01 08:33:03 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Nov 01 08:33:03 volumiobpi volumio[996]: info: In handleBrowseUri, curUri=spotify:artist:6tw6EpC9RgmSRZiZg0n22t Nov 01 08:33:05 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:7MnT7msJZg3XBAS0OTfGrB Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:7hkQhMFq4EOTYwX3I7cgmA Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:46s6p0tsgRBfzWriIg3w9o Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:6Pa6VpdGS8OfiVOEnNAHHw Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:2Pr6qNmiOxTdo8B6bs8x8x Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:7uscfoAoI65JcSY4NyHg1t Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:6ttKOudrrD5yjt4saUjhNa Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:1bqRtNOcT1QiV1j87IoATA Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:4RLp0EpcPdMHHoHmYIMWGH Nov 01 08:33:05 volumiobpi volumio[996]: info: Preloading song: spotify:track:4ILX2CDYdkqIqiVsIDE0Yy Nov 01 08:33:05 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:05 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:05 volumiobpi volumio[996]: info: No valid Plugin REST Endpoint Nov 01 08:33:08 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 08:33:08 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 08:33:08 volumiobpi volumio[996]: info: Discovery: Getting this device information Nov 01 08:33:08 volumiobpi volumio[996]: info: CoreCommandRouter::volumioGetState Nov 01 08:33:08 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:08 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 08:33:08 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::ClearQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::clearPlayQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:09 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7MnT7msJZg3XBAS0OTfGrB Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:7MnT7msJZg3XBAS0OTfGrB in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:7MnT7msJZg3XBAS0OTfGrB Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7MnT7msJZg3XBAS0OTfGrB","service":"spop","name":"Tempo Perdido","artist":"Legião Urbana","album":"Dois","type":"song","duration":302,"albumart":"https://i.scdn.co/image/ab67616d0000b2731eb5e996639036a49b09f1e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPlay Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::play index 0 Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:09 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7hkQhMFq4EOTYwX3I7cgmA Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:7hkQhMFq4EOTYwX3I7cgmA in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:7hkQhMFq4EOTYwX3I7cgmA Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:46s6p0tsgRBfzWriIg3w9o Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:46s6p0tsgRBfzWriIg3w9o in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:46s6p0tsgRBfzWriIg3w9o Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6Pa6VpdGS8OfiVOEnNAHHw Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:6Pa6VpdGS8OfiVOEnNAHHw in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6Pa6VpdGS8OfiVOEnNAHHw Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:2Pr6qNmiOxTdo8B6bs8x8x Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:2Pr6qNmiOxTdo8B6bs8x8x in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:2Pr6qNmiOxTdo8B6bs8x8x Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7uscfoAoI65JcSY4NyHg1t Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:7uscfoAoI65JcSY4NyHg1t in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:7uscfoAoI65JcSY4NyHg1t Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6ttKOudrrD5yjt4saUjhNa Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:6ttKOudrrD5yjt4saUjhNa in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6ttKOudrrD5yjt4saUjhNa Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:1bqRtNOcT1QiV1j87IoATA Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:1bqRtNOcT1QiV1j87IoATA in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:1bqRtNOcT1QiV1j87IoATA Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:4RLp0EpcPdMHHoHmYIMWGH Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:4RLp0EpcPdMHHoHmYIMWGH in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:4RLp0EpcPdMHHoHmYIMWGH Nov 01 08:33:09 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:4ILX2CDYdkqIqiVsIDE0Yy Nov 01 08:33:09 volumiobpi volumio[996]: info: Exploding uri spotify:track:4ILX2CDYdkqIqiVsIDE0Yy in service spop Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:4ILX2CDYdkqIqiVsIDE0Yy Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::play index undefined Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:09 volumiobpi volumio[996]: info: CoreStateMachine::startPlaybackTimer Nov 01 08:33:09 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:09 volumiobpi volumio[996]: info: [1761996789463] ControllerSpotify::clearAddPlayTrack Nov 01 08:33:09 volumiobpi volumio[996]: info: Sending Spotify command with payload to local API: /player/play Nov 01 08:33:09 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:09-03:00" level=debug msg="resolved context of track" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:09 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:09-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:09 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:09-03:00" level=debug msg="loading track (paused: false, position: 2ms)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2Pr6qNmiOxTdo8B6bs8x8x","service":"spop","name":"Quase Sem Querer","artist":"Legião Urbana","album":"Dois","type":"song","duration":280,"albumart":"https://i.scdn.co/image/ab67616d0000b2731eb5e996639036a49b09f1e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7uscfoAoI65JcSY4NyHg1t","service":"spop","name":"Ainda É Cedo","artist":"Legião Urbana","album":"Legião Urbana","type":"song","duration":237,"albumart":"https://i.scdn.co/image/ab67616d0000b2736b5b039d04b1a57e39a7020b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7hkQhMFq4EOTYwX3I7cgmA","service":"spop","name":"Será","artist":"Legião Urbana","album":"Legião Urbana","type":"song","duration":150,"albumart":"https://i.scdn.co/image/ab67616d0000b2736b5b039d04b1a57e39a7020b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Pa6VpdGS8OfiVOEnNAHHw","service":"spop","name":"Eduardo E Mônica","artist":"Legião Urbana","album":"Dois","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab67616d0000b2731eb5e996639036a49b09f1e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:09 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:46s6p0tsgRBfzWriIg3w9o","service":"spop","name":"Pais E Filhos","artist":"Legião Urbana","album":"As Quatro Estações","type":"song","duration":308,"albumart":"https://i.scdn.co/image/ab67616d0000b273dc6853bcee42e6ccbb8cc89d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:10 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:10-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 01 08:33:10 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:10-03:00" level=trace msg="emitting websocket event: will_play" Nov 01 08:33:10 volumiobpi volumio[996]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7MnT7msJZg3XBAS0OTfGrB","uri":"spotify:track:7MnT7msJZg3XBAS0OTfGrB","play_origin":"go-librespot"}} Nov 01 08:33:10 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:10-03:00" level=debug msg="selected format OGG_VORBIS_320 (9522332f1b70cbf91493d0cd3b3ffb871b045636)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:10 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:10-03:00" level=debug msg="requested aes key for file 9522332f1b70cbf91493d0cd3b3ffb871b045636, gid: 7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:10 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:10-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="fetched first chunk of 23, total size is 11907348 bytes" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=trace msg="seek to 2ms (diff: 2ms, samples: 88, bytes: 0)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:7MnT7msJZg3XBAS0OTfGrB: ALSA error at snd_pcm_open: No such file or directory" Nov 01 08:33:11 volumiobpi volumio[996]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::ClearQueue Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::clearPlayQueue Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:11 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7MnT7msJZg3XBAS0OTfGrB Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:7MnT7msJZg3XBAS0OTfGrB Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPlay Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::play index 0 Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:11 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7hkQhMFq4EOTYwX3I7cgmA Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:7hkQhMFq4EOTYwX3I7cgmA Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:46s6p0tsgRBfzWriIg3w9o Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:46s6p0tsgRBfzWriIg3w9o Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6Pa6VpdGS8OfiVOEnNAHHw Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:6Pa6VpdGS8OfiVOEnNAHHw Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:2Pr6qNmiOxTdo8B6bs8x8x Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:2Pr6qNmiOxTdo8B6bs8x8x Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7uscfoAoI65JcSY4NyHg1t Nov 01 08:33:11 volumiobpi volumio[996]: info: Using cached record of: spotify:track:7uscfoAoI65JcSY4NyHg1t Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6ttKOudrrD5yjt4saUjhNa Nov 01 08:33:11 volumiobpi volumio[996]: info: Exploding uri spotify:track:6ttKOudrrD5yjt4saUjhNa in service spop Nov 01 08:33:11 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6ttKOudrrD5yjt4saUjhNa Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:1bqRtNOcT1QiV1j87IoATA Nov 01 08:33:11 volumiobpi volumio[996]: info: Exploding uri spotify:track:1bqRtNOcT1QiV1j87IoATA in service spop Nov 01 08:33:11 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:1bqRtNOcT1QiV1j87IoATA Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:4RLp0EpcPdMHHoHmYIMWGH Nov 01 08:33:11 volumiobpi volumio[996]: info: Exploding uri spotify:track:4RLp0EpcPdMHHoHmYIMWGH in service spop Nov 01 08:33:11 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:4RLp0EpcPdMHHoHmYIMWGH Nov 01 08:33:11 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:4ILX2CDYdkqIqiVsIDE0Yy Nov 01 08:33:11 volumiobpi volumio[996]: info: Exploding uri spotify:track:4ILX2CDYdkqIqiVsIDE0Yy in service spop Nov 01 08:33:11 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:4ILX2CDYdkqIqiVsIDE0Yy Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::play index undefined Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:11 volumiobpi volumio[996]: info: CoreStateMachine::startPlaybackTimer Nov 01 08:33:11 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:11 volumiobpi volumio[996]: info: [1761996791445] ControllerSpotify::clearAddPlayTrack Nov 01 08:33:11 volumiobpi volumio[996]: info: Sending Spotify command with payload to local API: /player/play Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="resolved context of track" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 01 08:33:11 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:11-03:00" level=trace msg="emitting websocket event: will_play" Nov 01 08:33:11 volumiobpi volumio[996]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7MnT7msJZg3XBAS0OTfGrB","uri":"spotify:track:7MnT7msJZg3XBAS0OTfGrB","play_origin":"go-librespot"}} Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="selected format OGG_VORBIS_320 (9522332f1b70cbf91493d0cd3b3ffb871b045636)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="requested aes key for file 9522332f1b70cbf91493d0cd3b3ffb871b045636, gid: 7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="fetched first chunk of 23, total size is 11907348 bytes" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:7MnT7msJZg3XBAS0OTfGrB: ALSA error at snd_pcm_open: No such file or directory" Nov 01 08:33:12 volumiobpi volumio[996]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:12 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:12-03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:7MnT7msJZg3XBAS0OTfGrB" Nov 01 08:33:14 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ttKOudrrD5yjt4saUjhNa","service":"spop","name":"Faroeste Caboclo","artist":"Legião Urbana","album":"Que Pais E Este","type":"song","duration":547,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb7e0621a9cd1f3a15d4d4d2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:14 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1bqRtNOcT1QiV1j87IoATA","service":"spop","name":"Que Pais É Este","artist":"Legião Urbana","album":"Que Pais E Este","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb7e0621a9cd1f3a15d4d4d2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:14 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4RLp0EpcPdMHHoHmYIMWGH","service":"spop","name":"Índios","artist":"Legião Urbana","album":"Dois","type":"song","duration":257,"albumart":"https://i.scdn.co/image/ab67616d0000b2731eb5e996639036a49b09f1e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:14 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4ILX2CDYdkqIqiVsIDE0Yy","service":"spop","name":"Quando O Sol Bater Na Janela Do Teu Quarto","artist":"Legião Urbana","album":"As Quatro Estações","type":"song","duration":193,"albumart":"https://i.scdn.co/image/ab67616d0000b273dc6853bcee42e6ccbb8cc89d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:14 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:14 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:14 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:14 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:19 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ttKOudrrD5yjt4saUjhNa","service":"spop","name":"Faroeste Caboclo","artist":"Legião Urbana","album":"Que Pais E Este","type":"song","duration":547,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb7e0621a9cd1f3a15d4d4d2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:19 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1bqRtNOcT1QiV1j87IoATA","service":"spop","name":"Que Pais É Este","artist":"Legião Urbana","album":"Que Pais E Este","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273fb7e0621a9cd1f3a15d4d4d2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:19 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4RLp0EpcPdMHHoHmYIMWGH","service":"spop","name":"Índios","artist":"Legião Urbana","album":"Dois","type":"song","duration":257,"albumart":"https://i.scdn.co/image/ab67616d0000b2731eb5e996639036a49b09f1e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:20 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4ILX2CDYdkqIqiVsIDE0Yy","service":"spop","name":"Quando O Sol Bater Na Janela Do Teu Quarto","artist":"Legião Urbana","album":"As Quatro Estações","type":"song","duration":193,"albumart":"https://i.scdn.co/image/ab67616d0000b273dc6853bcee42e6ccbb8cc89d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:20 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:20 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:20 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:20 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:21 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Nov 01 08:33:21 volumiobpi volumio[996]: info: In handleBrowseUri, curUri=spotify Nov 01 08:33:21 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:21 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:21 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:21 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:24 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:24-03:00" level=trace msg="sent dealer ping" Nov 01 08:33:24 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:24-03:00" level=trace msg="received dealer pong" Nov 01 08:33:25 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Nov 01 08:33:25 volumiobpi volumio[996]: info: In handleBrowseUri, curUri=spotify/myartists Nov 01 08:33:26 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:28 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Nov 01 08:33:28 volumiobpi volumio[996]: info: In handleBrowseUri, curUri=spotify:artist:3EA9hVIzKfFiQI0Kikz2wo Nov 01 08:33:30 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreStateMachine::ClearQueue Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:30 volumiobpi volumio[996]: info: CorePlayQueue::clearPlayQueue Nov 01 08:33:30 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:30 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:30 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:30 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:30 volumiobpi volumio[996]: info: Adding Item to queue: spotify:artist:3EA9hVIzKfFiQI0Kikz2wo Nov 01 08:33:30 volumiobpi volumio[996]: info: Exploding uri spotify:artist:3EA9hVIzKfFiQI0Kikz2wo in service spop Nov 01 08:33:30 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:artist:3EA9hVIzKfFiQI0Kikz2wo Nov 01 08:33:30 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:7zrpoAJte9o12TzawqgdD0 Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:6cPLCU7hKjgjvLWzCevl7R Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:3R8iDYXuFoCI1lBaJ3j07k Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:3zl7j5ua8mF4JDYuxrfo01 Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:0f4fq7Wp2B5qB4baIzS6I7 Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:5WHnE8MsLFHqSUwecrs7WO Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:6zlY4xmlgqvn4LxjzoS2mz Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:6ykkal4MnCob5AQxckVqj2 Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:3Gao7l3KQ6enfISaKabMPm Nov 01 08:33:30 volumiobpi volumio[996]: info: Preloading song: spotify:track:0tyWs7VaLmVvUkFXd9nyfj Nov 01 08:33:30 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:30 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:31 volumiobpi volumio[996]: info: No valid Plugin REST Endpoint Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:33 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:33 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPlay Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::play index 0 Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::play index undefined Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:33 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:33 volumiobpi volumio[996]: info: CoreStateMachine::startPlaybackTimer Nov 01 08:33:33 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 0 Nov 01 08:33:33 volumiobpi volumio[996]: info: [1761996813946] ControllerSpotify::clearAddPlayTrack Nov 01 08:33:33 volumiobpi volumio[996]: info: Sending Spotify command with payload to local API: /player/play Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=debug msg="resolved context of track" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=trace msg="emitting websocket event: will_play" Nov 01 08:33:34 volumiobpi volumio[996]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7zrpoAJte9o12TzawqgdD0","uri":"spotify:track:7zrpoAJte9o12TzawqgdD0","play_origin":"go-librespot"}} Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=debug msg="selected format OGG_VORBIS_320 (c432d8ad11b43a7dcc30b99205336314c8de5348)" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:34 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:34-03:00" level=debug msg="requested aes key for file c432d8ad11b43a7dcc30b99205336314c8de5348, gid: 7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=debug msg="fetched first chunk of 18, total size is 9330828 bytes" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi go-librespot[1714]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:7zrpoAJte9o12TzawqgdD0: ALSA error at snd_pcm_open: No such file or directory" Nov 01 08:33:35 volumiobpi volumio[996]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreStateMachine::ClearQueue Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:35 volumiobpi volumio[996]: info: CorePlayQueue::clearPlayQueue Nov 01 08:33:35 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:35 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:35-03:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:7zrpoAJte9o12TzawqgdD0" Nov 01 08:33:35 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:35 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:35 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:35 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7zrpoAJte9o12TzawqgdD0 Nov 01 08:33:35 volumiobpi volumio[996]: info: Exploding uri spotify:track:7zrpoAJte9o12TzawqgdD0 in service spop Nov 01 08:33:35 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:7zrpoAJte9o12TzawqgdD0 Nov 01 08:33:35 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6cPLCU7hKjgjvLWzCevl7R Nov 01 08:33:35 volumiobpi volumio[996]: info: Exploding uri spotify:track:6cPLCU7hKjgjvLWzCevl7R in service spop Nov 01 08:33:35 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6cPLCU7hKjgjvLWzCevl7R Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6cPLCU7hKjgjvLWzCevl7R","service":"spop","name":"Vivo per lei","artist":"Andrea Bocelli","album":"Bocelli (Remastered)","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b2737e69f0cf9685328522e66e14","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7zrpoAJte9o12TzawqgdD0","service":"spop","name":"Con Te Partirò","artist":"Andrea Bocelli","album":"Bocelli (Remastered)","type":"song","duration":250,"albumart":"https://i.scdn.co/image/ab67616d0000b2737e69f0cf9685328522e66e14","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:36 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:36 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPlay Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::play index 1 Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:36 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:36 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3R8iDYXuFoCI1lBaJ3j07k Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:3R8iDYXuFoCI1lBaJ3j07k in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:3R8iDYXuFoCI1lBaJ3j07k Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3zl7j5ua8mF4JDYuxrfo01 Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:3zl7j5ua8mF4JDYuxrfo01 in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:3zl7j5ua8mF4JDYuxrfo01 Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:0f4fq7Wp2B5qB4baIzS6I7 Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:0f4fq7Wp2B5qB4baIzS6I7 in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:0f4fq7Wp2B5qB4baIzS6I7 Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:5WHnE8MsLFHqSUwecrs7WO Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:5WHnE8MsLFHqSUwecrs7WO in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:5WHnE8MsLFHqSUwecrs7WO Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6zlY4xmlgqvn4LxjzoS2mz Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:6zlY4xmlgqvn4LxjzoS2mz in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6zlY4xmlgqvn4LxjzoS2mz Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6ykkal4MnCob5AQxckVqj2 Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:6ykkal4MnCob5AQxckVqj2 in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6ykkal4MnCob5AQxckVqj2 Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3Gao7l3KQ6enfISaKabMPm Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:3Gao7l3KQ6enfISaKabMPm in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:3Gao7l3KQ6enfISaKabMPm Nov 01 08:33:36 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:0tyWs7VaLmVvUkFXd9nyfj Nov 01 08:33:36 volumiobpi volumio[996]: info: Exploding uri spotify:track:0tyWs7VaLmVvUkFXd9nyfj in service spop Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:0tyWs7VaLmVvUkFXd9nyfj Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::play index undefined Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:36 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:36 volumiobpi volumio[996]: info: CoreStateMachine::startPlaybackTimer Nov 01 08:33:36 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:36 volumiobpi volumio[996]: info: [1761996816099] ControllerSpotify::clearAddPlayTrack Nov 01 08:33:36 volumiobpi volumio[996]: info: Sending Spotify command with payload to local API: /player/play Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=debug msg="resolved context of track" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3zl7j5ua8mF4JDYuxrfo01","service":"spop","name":"Perfect Symphony (Ed Sheeran & Andrea Bocelli)","artist":"Ed Sheeran","album":"Perfect Symphony (Ed Sheeran & Andrea Bocelli)","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b273baf9098edfd8605c55975c84","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3R8iDYXuFoCI1lBaJ3j07k","service":"spop","name":"Time To Say Goodbye","artist":"Sarah Brightman","album":"Romanza (Super Deluxe)","type":"song","duration":245,"albumart":"https://i.scdn.co/image/ab67616d0000b2739df74c0a49526bb424695bee","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=trace msg="emitting websocket event: will_play" Nov 01 08:33:36 volumiobpi volumio[996]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6cPLCU7hKjgjvLWzCevl7R","uri":"spotify:track:6cPLCU7hKjgjvLWzCevl7R","play_origin":"go-librespot"}} Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=debug msg="selected format OGG_VORBIS_320 (041bb5aa67ab5647c85dcf649947197cc72fa1cf)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=debug msg="requested aes key for file 041bb5aa67ab5647c85dcf649947197cc72fa1cf, gid: 6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:36 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:36-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="fetched first chunk of 21, total size is 10837388 bytes" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:6cPLCU7hKjgjvLWzCevl7R: ALSA error at snd_pcm_open: No such file or directory" Nov 01 08:33:37 volumiobpi volumio[996]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::ClearQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::clearPlayQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:37 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:7zrpoAJte9o12TzawqgdD0 Nov 01 08:33:37 volumiobpi volumio[996]: info: Using cached record of: spotify:track:7zrpoAJte9o12TzawqgdD0 Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6cPLCU7hKjgjvLWzCevl7R Nov 01 08:33:37 volumiobpi volumio[996]: info: Using cached record of: spotify:track:6cPLCU7hKjgjvLWzCevl7R Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPlay Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::play index 1 Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::addQueueItems Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::addQueueItems Nov 01 08:33:37 volumiobpi volumio[996]: info: Preload queue cleared Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3R8iDYXuFoCI1lBaJ3j07k Nov 01 08:33:37 volumiobpi volumio[996]: info: Using cached record of: spotify:track:3R8iDYXuFoCI1lBaJ3j07k Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3zl7j5ua8mF4JDYuxrfo01 Nov 01 08:33:37 volumiobpi volumio[996]: info: Using cached record of: spotify:track:3zl7j5ua8mF4JDYuxrfo01 Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:0f4fq7Wp2B5qB4baIzS6I7 Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:0f4fq7Wp2B5qB4baIzS6I7 in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:0f4fq7Wp2B5qB4baIzS6I7 Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:5WHnE8MsLFHqSUwecrs7WO Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:5WHnE8MsLFHqSUwecrs7WO in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:5WHnE8MsLFHqSUwecrs7WO Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6zlY4xmlgqvn4LxjzoS2mz Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:6zlY4xmlgqvn4LxjzoS2mz in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6zlY4xmlgqvn4LxjzoS2mz Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:6ykkal4MnCob5AQxckVqj2 Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:6ykkal4MnCob5AQxckVqj2 in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:6ykkal4MnCob5AQxckVqj2 Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:3Gao7l3KQ6enfISaKabMPm Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:3Gao7l3KQ6enfISaKabMPm in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:3Gao7l3KQ6enfISaKabMPm Nov 01 08:33:37 volumiobpi volumio[996]: info: Adding Item to queue: spotify:track:0tyWs7VaLmVvUkFXd9nyfj Nov 01 08:33:37 volumiobpi volumio[996]: info: Exploding uri spotify:track:0tyWs7VaLmVvUkFXd9nyfj in service spop Nov 01 08:33:37 volumiobpi volumio[996]: SPOTIFY: EXPLODING URI:spotify:track:0tyWs7VaLmVvUkFXd9nyfj Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::stop Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::play index undefined Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:37 volumiobpi volumio[996]: info: CoreStateMachine::startPlaybackTimer Nov 01 08:33:37 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:37 volumiobpi volumio[996]: info: [1761996817684] ControllerSpotify::clearAddPlayTrack Nov 01 08:33:37 volumiobpi volumio[996]: info: Sending Spotify command with payload to local API: /player/play Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="resolved context of track" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:37 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:37-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=trace msg="emitting websocket event: will_play" Nov 01 08:33:38 volumiobpi volumio[996]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6cPLCU7hKjgjvLWzCevl7R","uri":"spotify:track:6cPLCU7hKjgjvLWzCevl7R","play_origin":"go-librespot"}} Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="selected format OGG_VORBIS_320 (041bb5aa67ab5647c85dcf649947197cc72fa1cf)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="requested aes key for file 041bb5aa67ab5647c85dcf649947197cc72fa1cf, gid: 6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 08:33:38 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 08:33:38 volumiobpi volumio[996]: info: Discovery: Getting this device information Nov 01 08:33:38 volumiobpi volumio[996]: info: CoreCommandRouter::volumioGetState Nov 01 08:33:38 volumiobpi volumio[996]: info: CorePlayQueue::getTrack 1 Nov 01 08:33:38 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="fetched first chunk of 21, total size is 10837388 bytes" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: ALSA lib pcm_softvol.c:778:(softvol_load_control) Cannot open CTL hw:1 Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:6cPLCU7hKjgjvLWzCevl7R: ALSA error at snd_pcm_open: No such file or directory" Nov 01 08:33:38 volumiobpi volumio[996]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:38 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:38-03:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:39 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:39-03:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:6cPLCU7hKjgjvLWzCevl7R" Nov 01 08:33:41 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5WHnE8MsLFHqSUwecrs7WO","service":"spop","name":"Bésame Mucho","artist":"Andrea Bocelli","album":"Amor (Edición Especial En Español)","type":"song","duration":241,"albumart":"https://i.scdn.co/image/ab67616d0000b2737068ffbb5ab14ce041413edd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:41 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0f4fq7Wp2B5qB4baIzS6I7","service":"spop","name":"Vivo por Ella (feat. KAROL G)","artist":"Andrea Bocelli","album":"Duets (30th Anniversary)","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b27329d64d39f2f79169e74856eb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:41 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6zlY4xmlgqvn4LxjzoS2mz","service":"spop","name":"The Prayer","artist":"Céline Dion","album":"These are Special Times","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b2733095cc2cb7ce3079685d4787","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:41 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ykkal4MnCob5AQxckVqj2","service":"spop","name":"Quizás, Quizás, Quizás","artist":"Andrea Bocelli","album":"Pasión (Edición Especial En Español)","type":"song","duration":198,"albumart":"https://i.scdn.co/image/ab67616d0000b273fa183cbf631f42f83ffdee1a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:41 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Gao7l3KQ6enfISaKabMPm","service":"spop","name":"Vivo per lei - Italian - Spanish Version","artist":"Andrea Bocelli","album":"Romanza (Super Deluxe)","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b2739df74c0a49526bb424695bee","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0tyWs7VaLmVvUkFXd9nyfj","service":"spop","name":"Cuando Me Enamoro","artist":"Andrea Bocelli","album":"Amor (Edición Especial En Español)","type":"song","duration":235,"albumart":"https://i.scdn.co/image/ab67616d0000b2737068ffbb5ab14ce041413edd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:46 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:46 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:46 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5WHnE8MsLFHqSUwecrs7WO","service":"spop","name":"Bésame Mucho","artist":"Andrea Bocelli","album":"Amor (Edición Especial En Español)","type":"song","duration":241,"albumart":"https://i.scdn.co/image/ab67616d0000b2737068ffbb5ab14ce041413edd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0f4fq7Wp2B5qB4baIzS6I7","service":"spop","name":"Vivo por Ella (feat. KAROL G)","artist":"Andrea Bocelli","album":"Duets (30th Anniversary)","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b27329d64d39f2f79169e74856eb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ykkal4MnCob5AQxckVqj2","service":"spop","name":"Quizás, Quizás, Quizás","artist":"Andrea Bocelli","album":"Pasión (Edición Especial En Español)","type":"song","duration":198,"albumart":"https://i.scdn.co/image/ab67616d0000b273fa183cbf631f42f83ffdee1a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Gao7l3KQ6enfISaKabMPm","service":"spop","name":"Vivo per lei - Italian - Spanish Version","artist":"Andrea Bocelli","album":"Romanza (Super Deluxe)","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b2739df74c0a49526bb424695bee","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6zlY4xmlgqvn4LxjzoS2mz","service":"spop","name":"The Prayer","artist":"Céline Dion","album":"These are Special Times","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b2733095cc2cb7ce3079685d4787","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0tyWs7VaLmVvUkFXd9nyfj","service":"spop","name":"Cuando Me Enamoro","artist":"Andrea Bocelli","album":"Amor (Edición Especial En Español)","type":"song","duration":235,"albumart":"https://i.scdn.co/image/ab67616d0000b2737068ffbb5ab14ce041413edd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Nov 01 08:33:46 volumiobpi volumio[996]: info: CoreCommandRouter::volumioPushQueue Nov 01 08:33:46 volumiobpi volumio[996]: info: CorePlayQueue::saveQueue Nov 01 08:33:46 volumiobpi volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 01 08:33:46 volumiobpi volumio[996]: info: CorePlayQueue::getTrackBlock Nov 01 08:33:48 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 08:33:48 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Nov 01 08:33:48 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:48-03:00" level=trace msg="received accesspoint ping" Nov 01 08:33:48 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:48-03:00" level=trace msg="received accesspoint pong ack" Nov 01 08:33:50 volumiobpi volumio[996]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 01 08:33:54 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:54-03:00" level=trace msg="sent dealer ping" Nov 01 08:33:54 volumiobpi go-librespot[1714]: time="2025-11-01T08:33:54-03:00" level=trace msg="received dealer pong" Nov 01 08:34:02 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 08:34:02 volumiobpi volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Nov 01 08:34:07 volumiobpi volumio[996]: info: Starting Uninstall of plugin system_controller - ampswitch Nov 01 08:34:07 volumiobpi volumio[996]: info: Uninstalling plugin ampswitch Nov 01 08:34:07 volumiobpi volumio[996]: info: [ASDebug] Port: 24 Nov 01 08:34:07 volumiobpi volumio[996]: info: [ASDebug] Inverted: false Nov 01 08:34:07 volumiobpi volumio[996]: info: [ASDebug] Delay: 720 Nov 01 08:34:07 volumiobpi volumio[996]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 08:34:07 volumiobpi volumio[996]: TypeError: Cannot read property 'unexport' of undefined Nov 01 08:34:07 volumiobpi volumio[996]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:242:19) Nov 01 08:34:07 volumiobpi volumio[996]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:90:10) Nov 01 08:34:07 volumiobpi volumio[996]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Nov 01 08:34:07 volumiobpi volumio[996]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Nov 01 08:34:07 volumiobpi volumio[996]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1484:22) Nov 01 08:34:07 volumiobpi volumio[996]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1260:45) Nov 01 08:34:07 volumiobpi volumio[996]: at Socket.emit (events.js:400:28) Nov 01 08:34:07 volumiobpi volumio[996]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 01 08:34:07 volumiobpi volumio[996]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Nov 01 08:34:07 volumiobpi volumio[996]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 08:34:09 volumiobpi sudo[2750]: volumio : unable to resolve host volumiobpi Nov 01 08:34:09 volumiobpi sudo[2750]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Nov 01 08:34:09 volumiobpi sudo[2750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-01 08:33 Nov 01 08:34:09 volumiobpi sudo[2750]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="669bb6cc406bb77b11c5184fedb8a4dfd19ba4ec" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 29 Jul 2025 12:10:02 PM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="bananapim1" VOLUMIO_DEVICENAME="BananaPi M1" VOLUMIO_HASH="a856c34c22162ee39711d68f761997f2"